----- Original Message -----
From: "Ayal Baron" abaron@redhat.com To: "Simon Grinberg" simon@redhat.com Cc: vdsm-devel@lists.fedorahosted.org, "Dan Yasny" dyasny@redhat.com, "Saggi Mizrahi" smizrahi@redhat.com Sent: Thursday, 16 February, 2012 10:40:36 PM Subject: Re: [vdsm] flowID schema
----- Original Message -----
Lot's of stuff inline,
----- Original Message -----
From: "Saggi Mizrahi" smizrahi@redhat.com To: "Simon Grinberg" simon@redhat.com Cc: vdsm-devel@lists.fedorahosted.org, "Dan Yasny" dyasny@redhat.com, "Ayal Baron" abaron@redhat.com Sent: Thursday, February 16, 2012 7:02:02 PM Subject: Re: [vdsm] flowID schema
Pinning down specific moments where stuff went horribly wrong is usually quite simple. The only reason I can't think of for someone to track a problem is if there was a bug in the storage subsystem that cause a corruption that only became apparent later on. But this can't benefit from flowID.
I'm going to to day this again. I want to hear someone to give a case where this is useful. Don't say things like. "It will allow me to do X"
Allows me to do X is a valid argument if I believe X based on my experience (16 years out of which 4 of them is ovirt or whatever is was called at a specific time) debug is helpful or time saving.
The approach to this thing has been wrong from the word go. Someone suggested a *solution* (flowid) without stating the problem. What Saggi and I are trying to figure out is the problem and from there devise a proper solution. Because the problem has not been well defined (real use case with real logs to back it up) then this discussion is up in the air. We can argue about it till kingdom come but it's all theoretical and irrelevant. The fact of the matter is though that adding more IDs will clutter the log and that this is also adding code so it's more places for bugs, so there had better be a good reason for it otherwise we're making things more difficult to debug, not easier. The case where you had to spend 30m finding the right log is simply because you did not have enough info in the engine log before. Now that we do have this info (every call to vdsm and every result), there is absolutely no reason for you to waste so much time.
Wrt end users debugging flows - end users should get all the information they need in the engine log, the second they have to reach the host we've failed. Improving the logs on the hosts for the sake of the end users is like putting a band aid on a severed limb.
Unfortunately, this almost never happens. with 3.0 things improved, but debugging an ovirt issue is still a complicated business. If you want to define a problem and start working on the solution - this is it. The ultimate goal is to provide logging, that are 1. Uncluttered 2. easy to read and understand 3. do not require special training (you and Saggi know every verb, and you know what to look for. Imagine for a split second, that someone is not this vdsm-savvy) 4. FAST! (And by this I mean I am able to pinpoint the exact point in the log where things happened, or failed). Think of this in terms of kernel messages log - something goes wrong - you just look for the word "ERROR" and possibly something else (hinted in the GUI/API) in the log, and that puts you right at the spot. Can we somehow do the same? Can we, under the given conditions (lots of different entities cluttering the log with very verbose output; complex flows that for every action would prepare, check sanity, execute, rollback, finish, report; constant polling \hello repostat!\ that also adds to the clutter; etc etc) provide easily readable and quickly searchable logs, that a rookie can get through? 5. Easily follow-able (yes, I do want to be able to see exactly what the system does when I click a button in the GUI, flowID or whatever else, but it's something people do to understand and learn the system, think of additional scenarios, and to avoid shooting themselves in the foot). Following logs was the part that provided more understanding of what and how vdsm and the engine do, than two weeks of training and presentations, on the training I delivered, and I'm pretty sure Simon can back this up as well. 6. easy to inter-relate messages. If one flow kicked off another, I want to be able to see where task foo belongs to flow bar, and where another task foo belongs to another flow, even if they are both logging in parallel. Add the fact that we have a bunch of hosts and a managing server inter-relating like this.
This is what I would want to see. I am still convinced a flowID could provide at least a partial solution to all of the above, one way or another, but if you can provide a better solution, one that will adhere to #3, I'd love to hear of it
or "I know of a guy who spent 2 years doing X to VDSM\Engine logs"
I want an example like:
The user complained about X. So I had to do Y to figure out what is wrong and it was a pain.
I actually did it myself plenty of times - sometimes 20 hours strait just to understand what the hell was going wrong. Now think about a sysadmin or a front line support person?
To tell you that I recall the exact details of every case would be just too much.
The Only reason I can think of is someone trying to figure out what wrong knowing nothing about how VDSM\Engine works. While I just jump from place to place because I know what is going on, other people would just want to go step by step to get the complete picture.
Exactly - This person is called your end user. Unless it's only intended to use by the development community
But even with that I don't see why you would want to keep going from the Engine down to VDSM and back out again.
Other then that I just simply can't imagine a use case where I'd need to do the stuff you talk about. But again, I usually get my bug reports from QA and QE, and they are more skilled at bug reporting then the general public.
Right - you get your cases after someone else has actually did the initial time consuming search through the logs to get you around the place that the issue actually occurred.
Not true. I've done this plenty of times from the engine log down to vdsm. 99% of the bug reports contain a traceback and that is what you start with and it's really easy to find it in the logs. Most errors that have to do with 'flow' are in fact cross flows (e.g. one flow caused storage disconnect and second flow fails as a result, SPM performs action X which causes another host to fail in a different flow, etc).
People already analyzed the engine logs, ruled out other issues, got to the understanding that this issue is related to storage (in your case) and not to other modules in VDSM and even got to the suspected operation that have failed.
Guess who this someone was in numerous cases coming from customers in the middle of the night?
Further more, WHAT IS A FLOW? When does it start? When does it end? create Image is a flow? is the connect to the domain included? isn't it all just part of a big flow to create a VM? Does the engine even track it as a flow?
Flows depend on the debugger the problem and the scope.
Indeed :)
I didn't say it is easy, a flow definition is something elusive and may change context according to operation types.
PS. A good design actually starts with flows (user flows) and then translated to design.
Throwing another useless ID in the pile will give you nothing. What you want is to be able to map sophisticated connections between resources and operations inside every component and between them. For instance, in VDSM. To track a resource locking issues you use the resourceID. It crosses "flows". To debug connection issues you use the connection information (and soon, the reference ID). An it crosses "flows" as well.
I'm not saying that debugging Ovirt is easy. I'm just saying that this is not the solution IMHO. Good anchors to resources like taskIDs, connection reference IDs, domain IDs and resource IDs give you the ability to track whatever you want. You just need better tools to cross reference them across log files so that the log tricks I *know* are implemented in a way that everyone can use them.
Very good, if you'll write it then you don't need flows - but this tool needs to come with the engine :)
However you will loose the benefit of catching design/architectural issues that are often discovered when you put some thought into what are your flows while you do the design.
Don't get me wrong, I'm not saying that flows are the only valid solution, everything you say makes a lot of sense, and everything you've suggested is important and I'll vote for it. Flows (if we agree on this) should be on top not instead. Farther more flows will not solve all the illness of the world and even if you'll do everything that you've just mentioned above I'll be happy.
The problem is that the more you wait, the harder it is to do it.
In this specific case that so much is already written - it may make sense to try first everything you've suggested and then wait for a feedback on the new logs usability. As I've said flow ID is on top not instead. As long as you'll be willing to except more API changes :).
This is when good tools come in to play. Think about it like a DB. Should something be a table with an index or should it just be a view.
(more inline)
----- Original Message -----
From: "Simon Grinberg" simon@redhat.com To: "Saggi Mizrahi" smizrahi@redhat.com Cc: vdsm-devel@lists.fedorahosted.org, "Dan Yasny" dyasny@redhat.com, "Ayal Baron" abaron@redhat.com Sent: Thursday, February 16, 2012 11:07:34 AM Subject: Re: [vdsm] flowID schema
----- Original Message -----
From: "Saggi Mizrahi" smizrahi@redhat.com To: "Simon Grinberg" simon@redhat.com Cc: vdsm-devel@lists.fedorahosted.org, "Dan Yasny" dyasny@redhat.com, "Ayal Baron" abaron@redhat.com Sent: Thursday, February 16, 2012 5:18:26 PM Subject: Re: [vdsm] flowID schema
You could just cross check flowID (that is printed in RHEV-M to all the call IDs in that flow, It's a simple enough tool to make).
Also if you look at the way VDSM is heading you will see that just grepping for the flow ID will gradually give you a smaller and smaller picture of the actual flow.
- The new connection management means that the actual connect
is not a direct part of the flow anymore.
- We plan to have a similar mechanism for domains.
- The new image code will do a lot of things "out of band".
- There will be more flows using multiple hosts because of
SDM and the increased safety gained by sanlock and they will not share the flow ID in internal communication.
- Engine actually polls all tasks in a single thread (with
it's own flow ID? No flowID?) so even the actual result for async tasks might have a different flowID in the VDSM log.
OK so they may be a terminology mismatch here: A flow as an end user would see it is: Everything that happened since the moment he clicked "OK" and to the moment the operation failed succeeded. Same goes for internal/auto triggered actions in response to an event (Storage failure etc).
It may be composed as you notes above of several connections, multiple tasks etc. The flow ID as I see it is the linkage that makes sense in all of these. Everything that you've wrote above just convinces me that such an ID is a must.
I understood that. The point is that the system is too complex to be able to find certain operations to flows. If you connect in FlowX but use a resource provided by the connection in flowY. The connection breaks and you loose the resource. As long as you somehow pinned the flowID value to the connection object it might be logged as flowX. The actual problem happened in flowY.
This someone is called oVirt engine
My point is that the logical leaps required to extract only relevant data to a flow are impossible at run time as VDSM is too low in the stack to know the context and figure out what's related and what isn't. For simple log syncing you could just force users to use NTP.
Agree - This is why I've defined a flow as something initiated by the end user/event. It should not be up to VDSM to determine the flow ID it is given to it.
It is up to the engine to determine flow id.
In order to keep flowID sane in that kind of environment, there will have to be a lot of code moving that value around just to log it.
Indeed, write well once and serve many later, that is what coding is all about. If you do it while you code you'll simplify the external tools required while making even manual debug tasks more reasonable. And more important - faster
It is called Design for Debug!!! And in hardware world, it consumes 20% more resources. It saves much more afterwards.
Most important, it will save escalations to developers, meaning that a developer that will invest in that actually does this for his own sanity (unless he does not care :)). The easier it is to debug the system by the end user first then by community as an escalation point and only then developers, the more time you'll have to do what you love to do best - develop.
Remember, developers are few, community is larger and users (if you are lucky) are in order of magnitudes larger. Every effort you spend in the design phase to reduce escalations will reward you later.
What we really need is something like the systemd journal (http://bit.ly/vbZEBQ). The project is still in it's infancy but the actual ideas are solid.
- Always log in UTC
- Log in a query-able format with typed key\value pairs
instead of just free text messages
- Use MSGID for *some* of the more important log lines for
easy matching (and use UUID for MSGID instead of a rolling number)
That is a good start - always good to have regardless of the above discussion.
With this kind of format you can easily write tools that sync up logs and do any other post processing. It will also allow us to easily migrate to the systemd journal when it's available.
We could just log to an sqlite db but I have a felling the constant fsyncing\flocking will be a performance issue.
Some will agree, some will disagree, not sure that having another DB in the system is advisable.
So I suggest implementing this by having a log target which writes json objects and have a tool to put it all in an sqlite DB when necessary. This way you don't get a performance hit for doing something drastically different then appending to text files but you can later easily "pack" the logs to a db file that can easily be navigated, merged and processed.
You could get the "classic view" by just using the msg field from the json object for each line. You could do that without going through the "packing" process so it's instantly available.
I've been pondering this for quite some time and this might be a good excuse to give it a shot. As long as all the components in OVIRT write json objects we could merge all logs together to a single log db. You could then try and detect small time time drifts using heuristics and have a unified view of everything.
I can do a more in depth write up if people think it's a good direction to go to.
----- Original Message -----
From: "Simon Grinberg" simon@redhat.com To: "Ayal Baron" abaron@redhat.com, "Saggi Mizrahi" smizrahi@redhat.com Cc: vdsm-devel@lists.fedorahosted.org, "Dan Yasny" dyasny@redhat.com Sent: Wednesday, February 15, 2012 5:50:34 AM Subject: Re: [vdsm] flowID schema
Hi Ayal,
> > actual use case where someone would have actually > > benefited > > from > > this.
Sorry joining that late into the discussion.
Forget the automatic analyses/past issues recognition that may or may not be possible if we do have flow ID. (Personally I believe it's possible for known issues)
Think of large setups, not the few hosts setups that are running in the labs. Dozens of hosts, hundreds of VMs and tasks, running for few months. --->>> Huge logs (yes we even got 50G sized logs)
Now try to do what you and Saggy are suggesting said, yes it will work!!! Sometimes it is the only approach that will be possible.
But what about efficiency?
Some times I found myself spending 30 minutes just getting to the files that I need to view and to the approximate location of the error. If you have a flow ID you can have a tool that will extract all the relevant information from all the hosts participating in that flow and correlate that with the rhevm.log as the anchor.
(Valdik actually wrote a tool that follows the SPM and creates an SPM log no matter on which host it resides - this allowed tracking flows and proved itself useful and time saving, especially since when storage issues begin SPM tends to move around :))
In addition to that think about skill levels, For you it's very easy to go and debug, you wrote the code, you know what to expect and what is the normal behavior (most of the time). But what about others? When encountering an issue within a flow for a front line or a customer self debug the easiest way will be to actually compare it to the same flow that succeed (if exist) and understand what was supposed to happen next (or before) and did not. I actually used that technique a lot. Again a flow ID will save time. All you have to do is extract an identical flow that worked using the flow-extractor utility and then compare.
I agree that when you get to the really tough cases, they will span across flows and your only alternative may be just to dig in. However for many others, flows tracking will save support calls, support escalations and will considerably help with education. For 2.2 we had Marina going into the code and documenting flows, so support people can learn what to expect and what to look for in the logs.
I believe it will also help engineering, lot's of times I had to gather 3 engineers and sat together just to understand a flow in order to debug an issue or understand what to expect if someone complained about a weird behavior. Since each of them only new what his part is doing - all had to go into their code and discuss. With flow ID you can just extract the flow and easily see what is being done (you may find out as happened before that it's not exactly what they meant to do)
In short, if we aim to look at RHEV as a system, flows are helpful in many aspects. Instead of having discrete components and requiring a high level of expertise and spending a lot of time (finding the right spot) to debug even minor issues you can look at a system and easily get (most of the time), understand what to expect and get to the most relevant logs fairly fast.
Simon.
----- Original Message ----- > From: "Dan Yasny" dyasny@redhat.com > To: "Ayal Baron" abaron@redhat.com > Cc: "Simon Grinberg" simon@redhat.com, > vdsm-devel@lists.fedorahosted.org > Sent: Friday, February 10, 2012 4:01:01 PM > Subject: Re: [vdsm] flowID schema > > > > ----- Original Message ----- > > From: "Ayal Baron" abaron@redhat.com > > To: "Dan Yasny" dyasny@redhat.com > > Cc: "Simon Grinberg" simon@redhat.com, > > vdsm-devel@lists.fedorahosted.org > > Sent: Friday, 10 February, 2012 3:51:01 PM > > Subject: Re: [vdsm] flowID schema > > > > > > > > ----- Original Message ----- > > > > > > > > > ----- Original Message ----- > > > > From: "Ayal Baron" abaron@redhat.com > > > > To: "Dan Yasny" dyasny@redhat.com > > > > Cc: "Simon Grinberg" simon@redhat.com, > > > > vdsm-devel@lists.fedorahosted.org > > > > Sent: Friday, 10 February, 2012 2:55:46 PM > > > > Subject: Re: [vdsm] flowID schema > > > > > > > > > > > > > > > > ----- Original Message ----- > > > > > > > > > > > > > > > ----- Original Message ----- > > > > > > From: "Ayal Baron" abaron@redhat.com > > > > > > To: "Dan Yasny" dyasny@redhat.com > > > > > > Cc: "Simon Grinberg" simon@redhat.com, > > > > > > vdsm-devel@lists.fedorahosted.org > > > > > > Sent: Friday, 10 February, 2012 12:50:04 AM > > > > > > Subject: Re: [vdsm] flowID schema > > > > > > > > > > > > > > > > > > > > > > > > ----- Original Message ----- > > > > > > > > From: "Saggi Mizrahi" smizrahi@redhat.com > > > > > > > > To: "Keith Robertson" kroberts@redhat.com > > > > > > > > Cc: "VDSM Project Development" > > > > > > > > vdsm-devel@lists.fedorahosted.org > > > > > > > > Sent: Thursday, February 9, 2012 2:24:44 PM > > > > > > > > Subject: Re: [vdsm] flowID schema > > > > > > > > > > > > > > > > -1 > > > > > > > > > > > > > > > > I agree that for messaging environment > > > > > > > > having > > > > > > > > a > > > > > > > > Message > > > > > > > > ID > > > > > > > > is > > > > > > > > a > > > > > > > > must > > > > > > > > because you sometimes don't have a > > > > > > > > particular > > > > > > > > target > > > > > > > > so > > > > > > > > when > > > > > > > > you > > > > > > > > get > > > > > > > > a response you need to know what this node > > > > > > > > is > > > > > > > > actually > > > > > > > > responding > > > > > > > > to. > > > > > > > > > > > > > > > > The message ID could be composed with > > > > > > > > <FLOWID><MSGID> > > > > > > > > so > > > > > > > > you > > > > > > > > can > > > > > > > > reuse the field. > > > > > > > > > > > > > > > > But that is all besides the point. > > > > > > > > > > > > > > > > I understand that someone might find it fun > > > > > > > > to > > > > > > > > go > > > > > > > > on > > > > > > > > following > > > > > > > > the > > > > > > > > entire flow in the Engine and in VDSM. But > > > > > > > > I > > > > > > > > would > > > > > > > > like > > > > > > > > to > > > > > > > > hear > > > > > > > > an > > > > > > > > actual use case where someone would have > > > > > > > > actually > > > > > > > > benefited > > > > > > > > from > > > > > > > > this. > > > > > > > > As I see it having VSDM return the task ID > > > > > > > > with > > > > > > > > every > > > > > > > > response > > > > > > > > (and > > > > > > > > not just for async tasks) is a lot more > > > > > > > > useful > > > > > > > > and > > > > > > > > correct. > > > > > > > > > > > > > > Actually, the only way to understand what > > > > > > > happened > > > > > > > in > > > > > > > a > > > > > > > certain > > > > > > > flow > > > > > > > is to follow it through. From the engine log > > > > > > > where > > > > > > > an > > > > > > > action > > > > > > > was > > > > > > > initiated, down to the hosts that did the > > > > > > > execution. > > > > > > > Everything > > > > > > > RHEV > > > > > > > does is a flow, and with no correlation > > > > > > > between > > > > > > > hosts > > > > > > > executing > > > > > > > parts of the same flow, troubleshooting turns > > > > > > > into > > > > > > > guesswork, > > > > > > > because the only contact point left is time, > > > > > > > which > > > > > > > is > > > > > > > useless > > > > > > > when > > > > > > > you're talking about vdsm - there are > > > > > > > sometimes > > > > > > > hundreds > > > > > > > of > > > > > > > log > > > > > > > records in a single second, and not every > > > > > > > host > > > > > > > is > > > > > > > in > > > > > > > absolute > > > > > > > sync > > > > > > > with every other. > > > > > > > > > > > > What are you talking about? you know exactly > > > > > > what > > > > > > operation > > > > > > the > > > > > > engine ran at vdsm level. > > > > > > > > > > Not always true. Haven't had much chance to > > > > > deeply > > > > > dive > > > > > into > > > > > 3.0 > > > > > logs, and if things changed there, it's already a > > > > > huge > > > > > step > > > > > in > > > > > the > > > > > right direction. > > > > > > > > engine logs now always log calls to vdsm. > > > > > > finally! :) > > > > > > > > > > > > > > > > > > If it's a task then you also have a task > > > > > > id which is a uuid so you don't need anything > > > > > > else. > > > > > > > > > > Right, but 1. not everything is a task and > > > > > > > > Perhaps that should be fixed... > > > > > > > > > 2. tasks spawn other tasks, and need to be > > > > > followed > > > > > through > > > > > for > > > > > that > > > > > > > > In vdsm? no they don't > > > > > > Err, ok, in the engine then. The point being, a flow > > > like > > > MoveMultipleImages (pardon my bad memory for > > > spelling) > > > spawns > > > several tasks, and even within those tasks there's > > > usually > > > more > > > than > > > a single flow. > > > > > > > > > > > > 3. long running tasks are hell to debug, because > > > > > they > > > > > span > > > > > several > > > > > log files and thousands lines of logs > > > > > > > > flowid would not solve this in any way. > > > > All you need to do to see the entire task is grep > > > > the > > > > taskID > > > > as > > > > the > > > > thread name is the taskID > > > > > > which causes me to > > > 1. jump between engine and vdsm logs, comparing task > > > IDs > > > and > > > actions. > > > 2. do it many times in case of a complex flow > > > > > > Seeing the entire thing on RHEV/oVirt as a system > > > would > > > make > > > a > > > better > > > picture, and being able to grep the entire set of > > > logs > > > for > > > a > > > single > > > ID is a huge plus, since it would produce one large > > > log > > > that > > > (hopefully, and if everything is done right) shows > > > the > > > full > > > flow, > > > step by step, everywhere it took place > > > > Which is never what you really want as it is pretty > > useless. > > What > > you want is the point of failure and a few hundred > > lines > > before. > > The problem is - the point of failure is not always the > point > with > the python traceback. This is why a flow should be > follow-able > > > The rest is just distraction which is the point of > > this > > thread. > > I > > have never encountered a case where I needed such a > > flow > > to > > debug > > an > > issue (even when it spread across multiple hosts). > > No, the rest is an indication of flow progress, which can > help > with > troubleshooting of issues that don't end in an error. > Like > performance and scalability issues > > > > > > > > > > > > > > > > > > > > > > In addition, now that engine logs results, you > > > > > > can > > > > > > just > > > > > > grep > > > > > > that > > > > > > instead of a flow id and land at the exact > > > > > > correct > > > > > > command > > > > > > and > > > > > > not > > > > > > have to figure out which out of the 5 run in > > > > > > this > > > > > > flow > > > > > > is > > > > > > the > > > > > > relevant one. > > > > > > > > > > Haven't seen that yet, but again, what are > > > > > results? > > > > > When > > > > > the > > > > > failure > > > > > is somewhere in the middle of the flow, the > > > > > resulting > > > > > failure > > > > > can > > > > > be > > > > > totally irrelevant. > > > > > > > > When you have the failure message then all you have > > > > to > > > > do > > > > is > > > > grep > > > > it > > > > in the log and reach the exact call that failed. > > > > Just > > > > search > > > > for > > > > "ERROR|FAILED" above that and you reach the place > > > > of > > > > error. > > > > > > It's the typical approach to logs, that works for > > > other > > > systems. > > > With > > > RHEV, just finding the traceback is never the > > > solution, > > > because > > > it > > > shows where everything finally went offhill, instead > > > of > > > where > > > the > > > error happened. > > > > > > > > > > > > > > > > > > > > > > > > If you could give a real example where this > > > > > > would > > > > > > be > > > > > > beneficial > > > > > > (i.e. > > > > > > log excerpts, how you correlated them and how > > > > > > flow > > > > > > id > > > > > > would > > > > > > have > > > > > > eased your job) that would be great. > > > > > > > > > > Don't have these handy, guess Vladik, who was > > > > > collecting > > > > > interesting > > > > > fail flows could have helped. > > > > > > > > > > > > > > > > Note that I've also discussed this with Yaniv > > > > > > from > > > > > > qe > > > > > > who > > > > > > said > > > > > > they > > > > > > don't really need it. > > > > > > > > > > I'm not saying I want to see a flow ID as such, > > > > > what > > > > > I > > > > > _am_ > > > > > saying > > > > > is > > > > > that flows are important, and we need an easy way > > > > > of > > > > > following > > > > > them > > > > > through. > > > > > When a user starts a process in the engine, it > > > > > should > > > > > be > > > > > clearly > > > > > logged and marked, then it should consistently > > > > > report > > > > > progress > > > > > and > > > > > interim outputs, say which host was picked for > > > > > what > > > > > action, > > > > > and > > > > > how > > > > > that action can be identified in the vdsm logs. > > > > > > > > That's fine (although periodic logging causes log > > > > overflow) > > > > > > Can't those be aggregated somehow? Or sent into a > > > different > > > log? > > > There was even an idea of maintaining a local db for > > > logging > > > instead > > > of plaintext, sqlite would serve for that purpose > > > > > > > > > > > > > > > > > We cannot rely on timing. We cannot rely on > > > > > everyone > > > > > knowing > > > > > obscure > > > > > engine/vdsm action naming conventions, that are > > > > > not > > > > > exactly > > > > > the > > > > > same > > > > > as they look in the GUI. A person with no > > > > > understanding > > > > > of > > > > > engine > > > > > and vdsm internals, should be able to easily > > > > > follow > > > > > an > > > > > action > > > > > through to conclusion, and understand what was > > > > > done > > > > > at > > > > > each > > > > > step, > > > > > what the system got in return and how it reacted. > > > > > And > > > > > all > > > > > of > > > > > these > > > > > actions should be clearly inter-related, so a > > > > > single > > > > > grep > > > > > can > > > > > select > > > > > a flow. > > > > > > > > > > If you prefer to go in the other direction, like > > > > > turning > > > > > everything > > > > > into a task, that can also work, but each task, > > > > > when > > > > > spawning > > > > > another, should very clearly show the relation as > > > > > well, > > > > > and > > > > > sets > > > > > of > > > > > tasks should be marked as sets. > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > A generic debugging scenario as I see it. > > > > > > > > > > > > > > > > 1. Something went wrong > > > > > > > > 2. You go looking in the ENGINE log trying > > > > > > > > to > > > > > > > > figure > > > > > > > > out > > > > > > > > what > > > > > > > > happend. > > > > > > > > 3. You see that ENGINE got SomeError. > > > > > > > > > > > > > > ok, the rest are all downhill. > > > > > > > > > > > > > > 4. You follow the failure back to the start > > > > > > > of > > > > > > > the > > > > > > > flow, > > > > > > > then > > > > > > > go > > > > > > > with > > > > > > > the flow to the point where the engine exited > > > > > > > to > > > > > > > vdsm > > > > > > > 5. switch over to vdsm logs, make sure you > > > > > > > have > > > > > > > the > > > > > > > timing > > > > > > > right > > > > > > > (with no flow ID that's the olny orientation > > > > > > > after > > > > > > > all) > > > > > > > 6. find the start of the vdsm-side flow, > > > > > > > follow > > > > > > > it > > > > > > > to > > > > > > > the > > > > > > > failure, > > > > > > > pray the error makes sense. > > > > > > > > > > > > > > In many cases the answer is not in the vdsm > > > > > > > failure > > > > > > > traceback > > > > > > > but > > > > > > > somewhere in the middle of the flow, with no > > > > > > > errors > > > > > > > reported, > > > > > > > this > > > > > > > is why we need a way to easily follow things > > > > > > > through. > > > > > > > Moreover, > > > > > > > the > > > > > > > logs should be readable enough to make sense > > > > > > > to > > > > > > > a > > > > > > > typical > > > > > > > sysadmin, > > > > > > > and not a RHEV expert. > > > > > > > > > > > > > > > 4. Check to see if this error makes sense > > > > > > > > imagining > > > > > > > > that > > > > > > > > VDSM > > > > > > > > is > > > > > > > > always right and is a black box. > > > > > > > > 5. You did your digging and now you think > > > > > > > > that > > > > > > > > VDSM > > > > > > > > is > > > > > > > > as > > > > > > > > fault. > > > > > > > > 6. Go look for the call that failed. (If we > > > > > > > > returned > > > > > > > > the > > > > > > > > taskID > > > > > > > > it's > > > > > > > > pretty simple to find that call). > > > > > > > > 7. Look around the call to check VDSM > > > > > > > > state. > > > > > > > > 8. Profit. > > > > > > > > > > > > > > > > There is never a point where you want to > > > > > > > > follow > > > > > > > > a > > > > > > > > whole > > > > > > > > flow > > > > > > > > call > > > > > > > > by > > > > > > > > call going back and forth, and even if you > > > > > > > > did > > > > > > > > having > > > > > > > > the > > > > > > > > VDSM > > > > > > > > taskID is a better anchor then flowID. > > > > > > > > > > > > > > not everything is a task, flow IDs would > > > > > > > unify > > > > > > > entire > > > > > > > flows, > > > > > > > and > > > > > > > make > > > > > > > following them easy. > > > > > > > > > > > > > > > > > > > > > > > VDSM is built in a way that every call > > > > > > > > takes > > > > > > > > in > > > > > > > > to > > > > > > > > account > > > > > > > > the > > > > > > > > current state only. Debugging it with an > > > > > > > > engine > > > > > > > > flow > > > > > > > > mindset > > > > > > > > is > > > > > > > > just > > > > > > > > wrong and distracting. I see it doing more > > > > > > > > harm > > > > > > > > the > > > > > > > > good > > > > > > > > by > > > > > > > > reinforcing bad debugging practices. > > > > > > > > > > > > > > Maybe you're right, though I can't see how > > > > > > > from > > > > > > > my > > > > > > > experience > > > > > > > so > > > > > > > far, > > > > > > > but following the flows is the only thing > > > > > > > that > > > > > > > got > > > > > > > cases > > > > > > > resolved. > > > > > > > Not event IDs making every possible error, > > > > > > > and > > > > > > > not > > > > > > > task > > > > > > > IDs > > > > > > > (though > > > > > > > these do have their uses) - slow and > > > > > > > meticulous > > > > > > > mapping > > > > > > > of > > > > > > > flows > > > > > > > to > > > > > > > log records. > > > > > > > > > > > > > > > > > > > > > > > ----- Original Message ----- > > > > > > > > > From: "Keith Robertson" > > > > > > > > > kroberts@redhat.com > > > > > > > > > To: "VDSM Project Development" > > > > > > > > > vdsm-devel@lists.fedorahosted.org > > > > > > > > > Sent: Thursday, February 9, 2012 1:34:43 > > > > > > > > > PM > > > > > > > > > Subject: Re: [vdsm] flowID schema > > > > > > > > > > > > > > > > > > On 02/09/2012 12:18 PM, Andrew Cathrow > > > > > > > > > wrote: > > > > > > > > > > > > > > > > > > > > ----- Original Message ----- > > > > > > > > > >> From: "Ayal Baron"abaron@redhat.com > > > > > > > > > >> To: "Dan > > > > > > > > > >> Kenigsberg"danken@redhat.com > > > > > > > > > >> Cc: "VDSM Project > > > > > > > > > >> Development"vdsm-devel@lists.fedorahosted.org > > > > > > > > > >> Sent: Monday, February 6, 2012 > > > > > > > > > >> 10:35:54 > > > > > > > > > >> AM > > > > > > > > > >> Subject: Re: [vdsm] flowID schema > > > > > > > > > >> > > > > > > > > > >> > > > > > > > > > >> > > > > > > > > > >> ----- Original Message ----- > > > > > > > > > >>> On Thu, Feb 02, 2012 at 10:32:49AM > > > > > > > > > >>> -0500, > > > > > > > > > >>> Saggi > > > > > > > > > >>> Mizrahi > > > > > > > > > >>> wrote: > > > > > > > > > >>>> flowID makes no sense after the > > > > > > > > > >>>> initial > > > > > > > > > >>>> API > > > > > > > > > >>>> call > > > > > > > > > >>>> as > > > > > > > > > >>>> stuff > > > > > > > > > >>>> like > > > > > > > > > >>>> cacheing\threadpools\samplingtasks\resources\asyncTasks > > > > > > > > > >>>> so > > > > > > > > > >>>> flowing > > > > > > > > > >>>> a flow like that will not give you > > > > > > > > > >>>> the > > > > > > > > > >>>> entire > > > > > > > > > >>>> picture > > > > > > > > > >>>> while > > > > > > > > > >>>> debugging. > > > > > > > > > >>>> > > > > > > > > > >>>> Also adding it now will make > > > > > > > > > >>>> everything > > > > > > > > > >>>> even > > > > > > > > > >>>> more > > > > > > > > > >>>> ugly. > > > > > > > > > >>>> You know what, just imagine I wrote > > > > > > > > > >>>> one > > > > > > > > > >>>> of > > > > > > > > > >>>> my > > > > > > > > > >>>> long > > > > > > > > > >>>> rambles > > > > > > > > > >>>> about > > > > > > > > > >>>> why I don't agree with doing this. > > > > > > > > > >>> I cannot imagine you write anything > > > > > > > > > >>> like > > > > > > > > > >>> that. > > > > > > > > > >>> Really. > > > > > > > > > >>> I > > > > > > > > > >>> do > > > > > > > > > >>> not > > > > > > > > > >>> understand why you object logging > > > > > > > > > >>> flowID > > > > > > > > > >>> on > > > > > > > > > >>> API > > > > > > > > > >>> entry > > > > > > > > > >>> point. > > > > > > > > > >> The question is, what problem is this > > > > > > > > > >> really > > > > > > > > > >> trying > > > > > > > > > >> to > > > > > > > > > >> solve > > > > > > > > > >> and > > > > > > > > > >> is > > > > > > > > > >> there a simpler and less obtrusive > > > > > > > > > >> solution > > > > > > > > > >> to > > > > > > > > > >> that > > > > > > > > > >> problem? > > > > > > > > > > correlating logs between ovirt engine > > > > > > > > > > and > > > > > > > > > > potentially > > > > > > > > > > multiple > > > > > > > > > > vdsm > > > > > > > > > > nodes is a nightmare. It requires a lot > > > > > > > > > > skill > > > > > > > > > > to > > > > > > > > > > follow > > > > > > > > > > a > > > > > > > > > > transaction through from the front end > > > > > > > > > > all > > > > > > > > > > the > > > > > > > > > > way > > > > > > > > > > to > > > > > > > > > > the > > > > > > > > > > node, > > > > > > > > > > and even multiple nodes (eg actions on > > > > > > > > > > spm, > > > > > > > > > > then > > > > > > > > > > actions > > > > > > > > > > on > > > > > > > > > > other > > > > > > > > > > node to run a vm). > > > > > > > > > > Having a way to correlate the logs and > > > > > > > > > > follow > > > > > > > > > > a > > > > > > > > > > single > > > > > > > > > > event/flow > > > > > > > > > > is vital. > > > > > > > > > > > > > > > > > > > +1 > > > > > > > > > > > > > > > > > > Knowing what command caused a sequence of > > > > > > > > > events > > > > > > > > > in > > > > > > > > > VDSM > > > > > > > > > would > > > > > > > > > be > > > > > > > > > really > > > > > > > > > helpful particularly in a threaded > > > > > > > > > environment. > > > > > > > > > Further, > > > > > > > > > wouldn't > > > > > > > > > such > > > > > > > > > an ID be helpful in an asynchronous > > > > > > > > > request/response > > > > > > > > > model? > > > > > > > > > I'm > > > > > > > > > not > > > > > > > > > sure what the plans are for AMQP or even > > > > > > > > > if > > > > > > > > > there > > > > > > > > > are > > > > > > > > > plans, > > > > > > > > > but > > > > > > > > > I'd > > > > > > > > > think that something like this would be > > > > > > > > > crucial > > > > > > > > > for > > > > > > > > > an > > > > > > > > > async > > > > > > > > > response. > > > > > > > > > So, if you implemented it you might be > > > > > > > > > killing > > > > > > > > > 2 > > > > > > > > > birds > > > > > > > > > with > > > > > > > > > 1 > > > > > > > > > stone. > > > > > > > > > > > > > > > > > > FYI: If you want to see examples of other > > > > > > > > > systems > > > > > > > > > that > > > > > > > > > use > > > > > > > > > similar > > > > > > > > > concepts, take a look at the correlation > > > > > > > > > ID > > > > > > > > > in > > > > > > > > > JMS. > > > > > > > > > > > > > > > > > > Cheers, > > > > > > > > > Keith > > > > > > > > > > > > > > > > > > > > > > > > > > > >>> _______________________________________________ > > > > > > > > > >>> vdsm-devel mailing list > > > > > > > > > >>> vdsm-devel@lists.fedorahosted.org > > > > > > > > > >>> https://fedorahosted.org/mailman/listinfo/vdsm-devel > > > > > > > > > >>> > > > > > > > > > >> _______________________________________________ > > > > > > > > > >> vdsm-devel mailing list > > > > > > > > > >> vdsm-devel@lists.fedorahosted.org > > > > > > > > > >> https://fedorahosted.org/mailman/listinfo/vdsm-devel > > > > > > > > > >> > > > > > > > > > > _______________________________________________ > > > > > > > > > > vdsm-devel mailing list > > > > > > > > > > vdsm-devel@lists.fedorahosted.org > > > > > > > > > > https://fedorahosted.org/mailman/listinfo/vdsm-devel > > > > > > > > > > > > > > > > > > _______________________________________________ > > > > > > > > > vdsm-devel mailing list > > > > > > > > > vdsm-devel@lists.fedorahosted.org > > > > > > > > > https://fedorahosted.org/mailman/listinfo/vdsm-devel > > > > > > > > > > > > > > > > > _______________________________________________ > > > > > > > > vdsm-devel mailing list > > > > > > > > vdsm-devel@lists.fedorahosted.org > > > > > > > > https://fedorahosted.org/mailman/listinfo/vdsm-devel > > > > > > > > > > > > > > > > > > > > > > > > > > > > > -- > > > > > > > > > > > > > > > > > > > > > > > > > > > > Regards, > > > > > > > > > > > > > > Dan Yasny > > > > > > > Red Hat Israel > > > > > > > +972 9769 2280 > > > > > > > _______________________________________________ > > > > > > > vdsm-devel mailing list > > > > > > > vdsm-devel@lists.fedorahosted.org > > > > > > > https://fedorahosted.org/mailman/listinfo/vdsm-devel > > > > > > > > > > > > > > > > > > > > > > > -- > > > > > > > > > > > > > > > > > > > > Regards, > > > > > > > > > > Dan Yasny > > > > > Red Hat Israel > > > > > +972 9769 2280 > > > > > > > > > > > > > > > -- > > > > > > > > > > > > Regards, > > > > > > Dan Yasny > > > Red Hat Israel > > > +972 9769 2280 > > > > > > > -- > > > > Regards, > > Dan Yasny > Red Hat Israel > +972 9769 2280 >