Forseti Instrumentation using OpenCensus by red2k18 · Pull Request #2317 · forseti-security/forseti-security

red2k18 · 2018-11-29T23:40:37Z

This PR implements below functionalities as part of instrumentation on Forseti using OpenCensus:

Core tracing for gRPC Server/Client
Tracing integration libraries (requests, sqlalchemy)
Added spans to track the time taken by each method in the process of running end-to-end gRPC
services thereby figuring out long-running methods to optimize.

…Stackdriver Trace

* Shorten import statements * Fix > 80 characters lines * Fix unittests by falling back on FileExporter

…n / off (#2) * Add support for additional interceptors. * Add server CLI flag `--enable-tracing`. * Make tracing libraries optional. Install them using `pip install .[tracing]`. * Pass `--enable-tracing` in `systemctl` script (default toggle for deployments) * Add logging to exporter and tracer

* Add tracing libs * Style fixes, consistent naming * Fix linting + add tests

blueandgold

In looking at your actual results, there are a few things that are missing or can be added to be more helpful.

The CAI operations are not shown
Resource from API calls are not shown, for example gsuite, all the iter and fetch methods
Resources from CAI calls are not show, all the iter and fetch methods

blueandgold · 2019-08-08T22:39:11Z

+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+"""Forseti OpenCensus gRPC tracing setup."""


Can you please point me to the where the outer_wrapper, inner_wrapper pattern is documented or re-implemented from? My ultimate question is if these code are necessary to add to our codebase.

ocervell · 2019-08-09T13:09:02Z

@blueandgold Would you mind if we add that as a subsequent PR ?

This one was supposed to be a base for tracing (core tracing setup), but I'm open to meet up with Forseti team to determine what's to be traced further and make more PRs.

It's been a while that this PR has been open (and stalled multiple times), I'd like to see this merged asap if possible, especially when this is interleaved with the Terraform PR that was already reverted once because this one didn't make it in the last release.

Also, seems like tracing deeper functions would fit more with profiling (using e.g Stackdriver Profiling), and not tracing. Tracing is intended to understand overall latency of gRPC / HTTP calls and understand dependencies between services. Profiling will help with debugging time / perf for individual methods. We can add Stackdriver Profiling in a separate PR as well, using the same logic with an --enable_profiling flag.

Thanks !

…ensus > 1.0.0

blueandgold · 2019-08-09T16:11:21Z

Thanks @ocervell for the great explanation here. A few thoughts:

If tracing is what you described (overall latency of gRPC / HTTP calls, and dependencies between services), then we should at a minimum be able to see API calls for CAI, GSuite, or any other APIs calls that we might not be aware of, and we want to spot.

Inventory Create
  |__ client sends request
  |__ server handles request
      |__ server gets CAI data
           |__ server process CAI data
                 |__ server starts crawling
                       |__ server makes X API calls
                       |__ server writes to gcp_inventory table
  |__ server returns response 
  |__ client receives response

As for workflow, it would be nice to keep the work going in this feature branch, and merge it into dev when the feature is finished. Otherwise, we do releases on a biweekly schedule, and it would not be a great user experience if this is released when not completely finished.

What we ultimately want is to answer is the question of Why does inventory take so long. Which we can currently get from pyflame, where we can see the call stack over time. (time is x-axis, call stack is y-axis). If we can get this with profiling, then that would be great.

We can meet to discuss more on this.

ocervell · 2019-08-09T17:27:07Z

Agree with the comment on tracing API calls, however there is no support for this in the opencensus-python library yet: support exists for httplib and requests library, but seems like we're using a different library for GCP API calls (httplib2). I've opened an issue in opencensus-python to add support for httplib2, but it wasn't addressed yet.

Tracing can help to identify slow services, but is not often used to investigate which functions have performance issues. We chose to add detailed traces and spans because at that time, the Stackdriver Profiler was not available for Python3 and Stackdriver Trace was already GA. Traces can also be useful when correlated with logs when incidents happen (see this excellent post). That would have been part 2 of this work.

Seems like profiling can fit your specific use case better, which is to debug unidentified slow functions. I recommend using pyflame or trying out the Stackdriver Profiler (Beta) (see here and here) to the codebase to find which functions / methods are slow.

Keeping this PR up-to-date with dev for more than 8 months has been a challenge and is consuming a lot of my time: I'm running out of bandwith to keep doing it. Please close this PR if the team considers that tracing addition is not valuable to Forseti.

blueandgold · 2019-08-12T16:11:46Z

Another item that is worth mentioning: the 85,000 ms (1.4 minutes) in the result is the tracing time, not the time to create inventory, which is what we need to measure & analyze how long inventory is taking.

blueandgold · 2019-08-14T06:58:34Z

Hi @ocervell, thanks for your great effort & work here. We will need to think about how to leverage it, given that we need to manually record the spans on all the functions that we want, vs identifying problem under the hood that we may not know about but need to find out easily. As well as what you mentioned, the need to support httplib2 for our API calls.

blueandgold · 2019-08-15T05:56:11Z

@red2k18 @ocervell On further testing this PR, I am not able to to see any tracing output when running in my local dev environment. This was working before on 8/8, and nothing has changed in my dev environment.

In my IDE output, I see a lot of these error messages like below. I found the original issue where @ocervell resolved with this PR. But I am not sure if or how this ties to the problem I'm experiencing. Any advice?

ERROR:root:StackdriverExporter failed to emit data.Dropping 600 objects from queue.
Traceback (most recent call last):
  File "/usr/local/google/home/henryc/venv/lib/python3.6/site-packages/opencensus/common/transports/async_.py", line 109, in _thread_main
    self.exporter.emit(data)
  File "/usr/local/google/home/henryc/venv/lib/python3.6/site-packages/opencensus/ext/stackdriver/trace_exporter/__init__.py", line 212, in emit
    stackdriver_spans.extend(self.translate_to_stackdriver(trace))
  File "/usr/local/google/home/henryc/venv/lib/python3.6/site-packages/opencensus/ext/stackdriver/trace_exporter/__init__.py", line 237, in translate_to_stackdriver
    set_attributes(trace)
  File "/usr/local/google/home/henryc/venv/lib/python3.6/site-packages/opencensus/ext/stackdriver/trace_exporter/__init__.py", line 77, in set_attributes
    set_monitored_resource_attributes(span)
  File "/usr/local/google/home/henryc/venv/lib/python3.6/site-packages/opencensus/ext/stackdriver/trace_exporter/__init__.py", line 84, in set_monitored_resource_attributes
    resource = monitored_resource.get_instance()
  File "/usr/local/google/home/henryc/venv/lib/python3.6/site-packages/opencensus/common/monitored_resource/monitored_resource.py", line 58, in get_instance
    gcp_metadata_config.GcpMetadataConfig().get_gce_metadata()))
  File "/usr/local/google/home/henryc/venv/lib/python3.6/site-packages/opencensus/common/resource/__init__.py", line 129, in __init__
    check_ascii_256(value)
  File "/usr/local/google/home/henryc/venv/lib/python3.6/site-packages/opencensus/common/resource/__init__.py", line 91, in check_ascii_256
    raise ValueError("Value is longer than 256 characters")
ValueError: Value is longer than 256 characters

blueandgold · 2019-08-15T19:40:01Z

Another thing to figure out for the release is why the UI is greyed out. This is from your project, and I am also seeing it too in my project.

blueandgold · 2019-08-15T21:39:48Z

The stackdriver error will be fixed by this PR in the Open Census python client library.
census-instrumentation/opencensus-python#761

blueandgold · 2019-08-19T05:56:50Z

Just want to report latency again. It's pretty bad: +9 seconds to run a simple inventory list command. Some testing is in the below screenshot. I believe this is from the CLI side of the code. @red2k18 @ocervell

blueandgold · 2019-08-19T06:00:05Z

I noticed a weird behavior. If I run the forseti inventory create command without restarting the server, I would see the all the inventory creates to be in the same trace. I would expect each inventory create to be in separate traces. @red2k18 @ocervell

If I restart the server, then the next time I run the inventory create command, a new trace would be produced.

blueandgold · 2019-08-19T06:01:57Z

        super(Crawler, self).__init__()
        self.config = config

+    @tracing.trace()


@red2k18 @ocervell Most of the methods in this class is decorated manually. Why not decorate on the Class once?

@blueandgold goal is to decorate only the methods that we need to trace, otherwise runtime will increase for the background thread exporting the spans. I'm not sure about which specific methods should be traced, so I've put it on most methods here. Let me know if you have an idea of which ones should / should not be traced.

red2k18 · 2019-08-19T15:58:03Z

@blueandgold tracing interceptors are added when server boots up which generates a new trace id dynamically. Until then same trace id is used. This is expected behavior.

red2k18 · 2019-08-19T16:05:15Z

@blueandgold it's normal for the runtime to go up when tracing is enabled (tracing is disabled by default ). This time will only go up with addition of spans. There is an open issue on this census-instrumentation/opencensus-python#249.

blueandgold · 2019-08-19T16:18:56Z

@red2k18

1: The latency is happening is even tracing is off on the server, please see the 3rd part of my screenshot, and my comment that this is possibly happening in the CLI side of the code

2: Are you saying that only one trace id is available each time that the server boots up? This seems counter-intuitive. My understanding is that each call to the server would generate it's own trace, so that we can detect variations of the calls. Can you show me documentation of what is the correct behavior here, or is this how it's implemented?

red2k18 · 2019-08-19T17:12:53Z

@blueandgold regarding latency, I'm not seeing ~10 seconds lag. Screenshot below

red2k18 · 2019-08-19T21:01:08Z

@blueandgold
Regarding #2 - Whenver the root span gets created, a new trace id is generated. The trace id is sent along with the request in the headers. Hence all the spans in the trace has the same trace id and each span has a different span id.

blueandgold · 2019-08-19T22:14:46Z

Cool, the latency has been verified by @kevensen to not be an issue, so it must be something in my environment.

@red2k18 For #2, I am reporting that multiple inventory creates gets grouped in the same trace. Why are inventory list requests showing up as separate traces when run sequentially? Why is this behavior different? You can see this screenshot.

ocervell · 2019-08-20T13:49:23Z

@c24t might be able to answer 2/ better than me, as he has more knowledge of how OC works

ocervell · 2019-08-20T13:52:06Z

+    return outer_wrapper
+
+
+def trace():


@c24t could you please review this decorator's code ? Trying to find something in there that would explain why trace_id for successive run is the same and does not seem to be reset. Thanks :)

note: this decorator could be added to OpenCensus code to get an easier way to trace multi-threaded functions - it automatically passes the tracer across separate contexts and provides an helpful way to pass it explicitely if needed.

blueandgold · 2019-10-08T23:18:07Z

Thanks for all the hard work here, but Cloud Profiler will meet our instrumentation needs, instead of Stackdriver Trace.

Olivier Cervello and others added 30 commits August 20, 2018 10:33

Add basic gRPC tracing to Forseti client/server to Stackdriver Trace

a43d01a

Update requirements.txt to include OpenCensus libs

a5825ac

Add client/server IAM roles for Cloud Trace API

5a54c68

Fix role typo

0f45cdd

Merge remote-tracking branch 'upstream/dev' into dev-instrumentation

2705238

Merge branch 'dev' into dev-instrumentation

0bdcb85

Merge branch 'dev' into dev-instrumentation

b29247d

Roll back to FileExporter as default if environment is not setup for …

f152f5b

…Stackdriver Trace

Fix syntax error

8e33ada

Fix pep8 formatting errors

6ccd720

Fix pep8 tests errors

8bcca4e

* Shorten import statements * Fix > 80 characters lines * Fix unittests by falling back on FileExporter

Move opencensus dep from requirements.txt to setup.py

5f2850a

Move google-cloud-trace dep from requirements.txt to setup.py

ac3b6a3

Install tracing libraries in client VM deployment

35c9e20

Merge branch 'dev' into dev-instrumentation

615d38b

Merge dev-instrumentation-1 (#3)

9372385

* Add tracing libs * Style fixes, consistent naming * Fix linting + add tests

Update utils.py

e086548

Merge branch 'dev' into dev-instrumentation

d8110df

Update forseti

e1bd3ae

Update tracing_test.py

aaba67b

Update tracing_test.py

fdd79bd

Update tracing_test.py

4a8c0cf

Update client.py

37fce59

Update tracing.py

f0f65ea

Update tracing_test.py

5e789d5

Update tracing_test.py

ae39376

Update utils_test.py

19b35f8

Update utils_test.py

b8a612f

Update utils_test.py

94dda94

Olivier Cervello added 2 commits August 8, 2019 13:53

Add tracing support for Dockerized installs

931de8f

Fix tests and add tracing libs to requirements.txt

798455e

blueandgold reviewed Aug 8, 2019

View reviewed changes

Remove opencensus-ext-sqlalchemy extension as incompatible with OpenC…

ddda817

…ensus > 1.0.0

kevensen mentioned this pull request Aug 12, 2019

Add OpenCensus parameters to charts forseti-security/helm-charts#26

Closed

blueandgold reviewed Aug 19, 2019

View reviewed changes

ocervell reviewed Aug 20, 2019

View reviewed changes

red2k18 removed their assignment Aug 21, 2019

blueandgold mentioned this pull request Aug 21, 2019

Add Cloud Profiler to Forseti server #3113

Merged

dekuhn added the priority: p3 Desirable enhancement or minor bug fix label Sep 16, 2019

blueandgold closed this Oct 8, 2019

red2k18 deleted the forseti-instrumentation branch November 5, 2019 18:34

Uh oh!

Conversation

red2k18 commented Nov 29, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

blueandgold left a comment

Choose a reason for hiding this comment

Uh oh!

blueandgold Aug 8, 2019

Choose a reason for hiding this comment

Uh oh!

ocervell commented Aug 9, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

blueandgold commented Aug 9, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ocervell commented Aug 9, 2019

Uh oh!

blueandgold commented Aug 12, 2019

Uh oh!

blueandgold commented Aug 14, 2019

Uh oh!

blueandgold commented Aug 15, 2019

Uh oh!

blueandgold commented Aug 15, 2019

Uh oh!

blueandgold commented Aug 15, 2019

Uh oh!

blueandgold commented Aug 19, 2019

Uh oh!

blueandgold commented Aug 19, 2019

Uh oh!

blueandgold Aug 19, 2019

Choose a reason for hiding this comment

Uh oh!

ocervell Aug 19, 2019

Choose a reason for hiding this comment

Uh oh!

red2k18 commented Aug 19, 2019

Uh oh!

red2k18 commented Aug 19, 2019

Uh oh!

blueandgold commented Aug 19, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

red2k18 commented Aug 19, 2019

Uh oh!

red2k18 commented Aug 19, 2019

Uh oh!

blueandgold commented Aug 19, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ocervell commented Aug 20, 2019

Uh oh!

ocervell Aug 20, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

blueandgold commented Oct 8, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

red2k18 commented Nov 29, 2018 •

edited

Loading

ocervell commented Aug 9, 2019 •

edited

Loading

blueandgold commented Aug 9, 2019 •

edited

Loading

blueandgold commented Aug 19, 2019 •

edited

Loading

blueandgold commented Aug 19, 2019 •

edited

Loading

ocervell Aug 20, 2019 •

edited

Loading