Raphael/agent http request errors by raphaelgavache · Pull Request #173 · DataDog/dd-trace-py

raphaelgavache · 2017-02-13T18:00:20Z

Summary

Log whenever an http error happens when dd-trace-py sends traces to the agent.
Every 60 seconds logs have the ERROR level,
Under 60 seconds between two http error the logs have DEBUG level

Testing

Added a test in py-integration in the TestWorker: test_worker_http_error_logging

adding handle_responde() from dd-trace-rb

adding response handling

…g/dd-trace-py into raphael/http_agent_request_errors

fixing

clutchski · 2017-02-13T21:53:19Z

+
+        # client error code
+        if 400 <= status_code <= 499:
+            log.error("Client error: #{}".format(response.msg))


we need some form of rate limiting here ... otherwise we could spam the log a lot.

periodically (every 1s)

small fix

changing how the the timer works

.stop() already used in python3 threading, changing name

Using AsyncWorker _target thread function to write the http log requests

flake8 fix

log on the Writer

quick fix

…request_errors

bad indent fix

small fix

clutchski · 2017-02-14T22:51:59Z


            time.sleep(1) # replace with a blocking pop.

+            # Logging the http errors


how can this work? what assigns to result_traces?

api uses the httplib python library to send the data

The request comes from the lib with the 3 attributes status, reason, msg
https://github.com/python-git/python/blob/master/Lib/httplib.py#L943

It is then transmitted here
https://github.com/DataDog/dd-trace-py/blob/raphael/agent_http_request_errors/ddtrace/api.py#L79

And then here
https://github.com/DataDog/dd-trace-py/blob/raphael/agent_http_request_errors/ddtrace/api.py#L56

Actually no errors are raised in case of 400-599 http errors

clutchski · 2017-02-14T22:52:17Z


+            # Logging the http errors
+            if result_traces and result_traces.status >= 400:
+                current_time = time.time()


nitpick: now = time.time()

clutchski · 2017-02-14T22:53:23Z

+                    log.error("traces to Agent: HTTP error status {}, reason {}, message {}".format(
+                        result_traces.status, result_traces.reason, result_traces.msg))
+                    last_error_ts = current_time
+                else:


i'd change this to:

log_level = log.debug if now > last_error_ts + LOG_ERR_INTERVAL: log_level = log.error last_error_ts = now log_level("traces ...")

it's a bit cleaner and easier to read

clutchski · 2017-02-14T22:54:11Z

+                else:
+                    log.debug("services to Agent: HTTP error status {}, reason {}, message {}".format(
+                        result_services.status, result_services.reason, result_services.msg))
+


can we add a test for this whole thing?

clutchski · 2017-02-14T22:58:58Z

+            # Logging the http errors
+            if result_traces and result_traces.status >= 400:
+                current_time = time.time()
+                if current_time > last_error_ts + 10:


i think that the default interval should be 60 or 120

talwai · 2017-02-15T22:45:17Z

+        'test to try the http log errors, to trigger it change'
+        + 'https://github.com/DataDog/dd-trace-py/blob/master/ddtrace/api.py#L78'
+        + 'to "conn.request("HEAD", endpoint, data, self._headers)"'
+        + 'skip TestAPITransport and TestAPIDowngrade as they will fail if you change PUT to HEAD')


i think more important than testing the log capture itself is testing that the timestamps you are using for tracking errors are correctly updated. this means forcing an error in the api, and ensuring that last_error_ts is updated to a reasonable value.

talwai · 2017-02-15T22:45:58Z

                    time.sleep(0.05)

    def _target(self):
+        last_error_ts = 0


think about moving this to an attribute on AgentWriter so it's easier to test against self.last_error_ts

talwai · 2017-02-15T22:47:23Z

+                if now > last_error_ts + LOG_ERR_INTERVAL:
+                    log_level = log.error
+                    last_error_ts = now
+                log_level("traces to Agent: HTTP error status {}, reason {}, message {}".format(


failed to send traces to Agent...

…g/dd-trace-py into raphael/agent_http_request_errors

palazzem

minor changes that you can double check! overall the approach is fine!

palazzem · 2017-03-16T14:14:25Z

@@ -0,0 +1,11 @@
+BLACKLIST_ENDPOINT = [


think this is the result of a conflict; don't think we need it

palazzem · 2017-03-16T14:16:19Z

+                          getattr(result_services, "msg", None))
+                result_services = None
+
+            time.sleep(1)  # replace with a blocking pop.


it's better to avoid any kind of sleep() in application code... why do we need that?

palazzem · 2017-03-16T14:18:24Z


-            time.sleep(1) # replace with a blocking pop.
+            log_level = log.debug
+            if result_traces and getattr(result_traces, "status", None) >= 400:


this code is the same as the block below... you can merge the two blocks or use a separated function like _log_error_status(...)

palazzem · 2017-03-16T14:27:19Z

+
+        logged_errors = log_handler.messages['error']
+        eq_(len(logged_errors), 1)
+        if PY2:


instead of using a switch, you can just:

ok_('failed_to_send traces to Agent: HTTP error status 400, reason Bad Request' in logged_errors[0])

or whatever is the string you want to check.

palazzem · 2017-03-16T14:27:42Z

+        self.tracer.writer.api = FlawedAPI(Tracer.DEFAULT_HOSTNAME, Tracer.DEFAULT_PORT)
+        tracer.trace('client.testing').finish()
+        tracer.trace('client.testing').finish()
+        eq_(tracer.writer._worker._last_error_ts, 0)


this check could be flaky because you're relying that this thread is faster than the API worker

for completness: https://gist.github.com/palazzem/e37915b5d7f7a981465a1cdaf365cc9a

…g/dd-trace-py into raphael/agent_http_request_errors

…llocator (#17664) ## Description This PR fixes a segmentation fault in the memory allocation profiler that occurs when a hook call races with `memalloc` start/stop operations. The issue arises from concurrent access to the saved allocator struct, which could be partially written while being read, resulting in`NULL` function pointers being dereferenced. The key indicator in that case is that `#1 0x0000000000000000` frame -- we are trying to execute a null function pointer. ```` Error UnixSignal: Process terminated with SEGV_MAPERR (SIGSEGV) #0 0x00007ff3c303a8d4 #1 0x0000000000000000 memalloc_alloc (/go/src/github.com/DataDog/apm-reliability/dd-trace-py/ddtrace/profiling/collector/_memalloc.cpp:68) #2 0x00007ff39dcb3b20 memalloc_alloc (/go/src/github.com/DataDog/apm-reliability/dd-trace-py/ddtrace/profiling/collector/_memalloc.cpp:68) #3 0x00007ff39dcb3b20 memalloc_malloc(void*, unsigned long) (/go/src/github.com/DataDog/apm-reliability/dd-trace-py/ddtrace/profiling/collector/_memalloc.cpp:80) #4 0x00007ff3c3087e1b PyUnicode_New #5 0x00007ff3c30889f4 #6 0x00007ff3c3170c84 #7 0x00007ff3c316b931 #8 0x00007ff3c31aaac8 #9 0x00007ff3c31033ac #10 0x00007ff3c310e2a6 PyObject_CallMethodObjArgs #11 0x00007ff3c310e46d #12 0x00007ff3c31a96c2 #13 0x00007ff3c3102fd7 PyObject_Vectorcall #14 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #15 0x00007ff3c323c094 #16 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #17 0x00007ff3c323c094 #18 0x00007ff3c30e997d PyObject_CallOneArg #19 0x00007ff3c306a480 _PyObject_GenericGetAttrWithDict #20 0x00007ff3c30c620d PyObject_GetAttr #21 0x00007ff3c32309e7 _PyEval_EvalFrameDefault #22 0x00007ff3c323c094 #23 0x00007ff3c312880e #24 0x00007ff3c30e917c _PyObject_MakeTpCall #25 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #26 0x00007ff3c323c094 #27 0x00007ff3c312880e #28 0x00007ff3c30e917c _PyObject_MakeTpCall #29 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #30 0x00007ff3c323c094 #31 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #32 0x00007ff3c323c094 #33 0x00007ff3c317d0fd #34 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #35 0x00007ff3c323c094 #36 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #37 0x00007ff3c323c094 #38 0x00007ff3c317d1b5 #39 0x00007ff3c3102fd7 PyObject_Vectorcall #40 0x00007ff3c3232f4a _PyEval_EvalFrameDefault #41 0x00007ff3c3240da5 #42 0x00007ff3c324112d #43 0x00007ff3c3233be1 _PyEval_EvalFrameDefault #44 0x00007ff3c323c094 #45 0x00007ff3c317d1b5 #46 0x00007ff3c3102fd7 PyObject_Vectorcall #47 0x00007ff3c3232f4a _PyEval_EvalFrameDefault #48 0x00007ff3c323c094 #49 0x00007ff3c31033ac #50 0x00007ff3c310358d PyObject_CallFunctionObjArgs #51 0x00007ff3bf7eb91d WraptBoundFunctionWrapper_call (/project/src/wrapt/_wrappers.c:3750) #52 0x00007ff3c3104055 _PyObject_Call #53 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #54 0x00007ff3c323c094 #55 0x00007ff3c317d23c #56 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #57 0x00007ff3c323c094 #58 0x00007ff3c310416f _PyObject_Call #59 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #60 0x00007ff3c3240da5 #61 0x00007ff3c324112d #62 0x00007ff3c3233be1 _PyEval_EvalFrameDefault #63 0x00007ff3c323c094 #64 0x00007ff3c317d1b5 #65 0x00007ff3c3102fd7 PyObject_Vectorcall #66 0x00007ff3c3232f4a _PyEval_EvalFrameDefault #67 0x00007ff3c323c094 #68 0x00007ff3c317d1b5 #69 0x00007ff3c310416f _PyObject_Call #70 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #71 0x00007ff3c323c094 #72 0x00007ff3c317d1b5 #73 0x00007ff3c310416f _PyObject_Call #74 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #75 0x00007ff3c323c094 #76 0x00007ff3c31033ac #77 0x00007ff3c310358d PyObject_CallFunctionObjArgs #78 0x00007ff3bf7eb91d WraptBoundFunctionWrapper_call (/project/src/wrapt/_wrappers.c:3750) #79 0x00007ff3c30e917c _PyObject_MakeTpCall #80 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #81 0x00007ff3c323c094 #82 0x00007ff3c317d518 #83 0x00007ff3c3155963 #84 0x00007ff3c315393d #85 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #86 0x00007ff3c323c094 #87 0x00007ff3c317d0fd #88 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #89 0x00007ff3c323c094 #90 0x00007ff3c317d0fd #91 0x00007ff3c317d518 #92 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #93 0x00007ff3c323c094 #94 0x00007ff3c30e9371 _PyObject_FastCallDictTstate #95 0x00007ff3c30e958d _PyObject_Call_Prepend #96 0x00007ff3c3109150 #97 0x00007ff3c3104055 _PyObject_Call #98 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #99 0x00007ff3c323c094 #100 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #101 0x00007ff3c30e958d _PyObject_Call_Prepend #102 0x00007ff3c3109150 #103 0x00007ff3c30e917c _PyObject_MakeTpCall #104 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #105 0x00007ff3c323c094 #106 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #107 0x00007ff3c30e958d _PyObject_Call_Prepend #108 0x00007ff3c3109150 #109 0x00007ff3c30e917c _PyObject_MakeTpCall #110 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #111 0x00007ff3c323c094 #112 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #113 0x00007ff3c30e958d _PyObject_Call_Prepend #114 0x00007ff3c3109150 #115 0x00007ff3c30e917c _PyObject_MakeTpCall #116 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #117 0x00007ff3c323c094 #118 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #119 0x00007ff3c30e958d _PyObject_Call_Prepend #120 0x00007ff3c3109150 #121 0x00007ff3c30e917c _PyObject_MakeTpCall #122 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #123 0x00007ff3c323c094 #124 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #125 0x00007ff3c30e958d _PyObject_Call_Prepend #126 0x00007ff3c3109150 #127 0x00007ff3c30e917c _PyObject_MakeTpCall #128 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #129 0x00007ff3c323c094 #130 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #131 0x00007ff3c30e958d _PyObject_Call_Prepend #132 0x00007ff3c3109150 #133 0x00007ff3c30e917c _PyObject_MakeTpCall #134 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #135 0x00007ff3c323c094 #136 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #137 0x00007ff3c30e958d _PyObject_Call_Prepend #138 0x00007ff3c3109150 #139 0x00007ff3c30e917c _PyObject_MakeTpCall #140 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #141 0x00007ff3c323c094 #142 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #143 0x00007ff3c30e958d _PyObject_Call_Prepend #144 0x00007ff3c3109150 #145 0x00007ff3c30e917c _PyObject_MakeTpCall #146 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #147 0x00007ff3c323c094 #148 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #149 0x00007ff3c30e958d _PyObject_Call_Prepend #150 0x00007ff3c3109150 #151 0x00007ff3c30e917c _PyObject_MakeTpCall #152 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #153 0x00007ff3c323c094 #154 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #155 0x00007ff3c30e958d _PyObject_Call_Prepend #156 0x00007ff3c3109150 #157 0x00007ff3c30e917c _PyObject_MakeTpCall #158 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #159 0x00007ff3c323c094 #160 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #161 0x00007ff3c30e958d _PyObject_Call_Prepend #162 0x00007ff3c3109150 #163 0x00007ff3c30e917c _PyObject_MakeTpCall #164 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #165 0x00007ff3c323c094 #166 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #167 0x00007ff3c30e958d _PyObject_Call_Prepend #168 0x00007ff3c3109150 #169 0x00007ff3c30e917c _PyObject_MakeTpCall #170 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #171 0x00007ff3c323c094 #172 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #173 0x00007ff3c30e958d _PyObject_Call_Prepend #174 0x00007ff3c3109150 #175 0x00007ff3c30e917c _PyObject_MakeTpCall #176 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #177 0x00007ff3c323c094 #178 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #179 0x00007ff3c30e958d _PyObject_Call_Prepend #180 0x00007ff3c3109150 #181 0x00007ff3c30e917c _PyObject_MakeTpCall #182 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #183 0x00007ff3c323c094 #184 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #185 0x00007ff3c30e958d _PyObject_Call_Prepend #186 0x00007ff3c3109150 #187 0x00007ff3c30e917c _PyObject_MakeTpCall #188 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #189 0x00007ff3c323c094 #190 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #191 0x00007ff3c323c094 #192 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #193 0x00007ff3c30e958d _PyObject_Call_Prepend #194 0x00007ff3c3109150 #195 0x00007ff3c30e917c _PyObject_MakeTpCall #196 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #197 0x00007ff3c323c094 #198 0x00007ff3c317d0fd #199 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #200 0x00007ff3c323c094 #201 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #202 0x00007ff3c323c094 #203 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #204 0x00007ff3c323c094 #205 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #206 0x00007ff3c323c094 #207 0x00007ff3c317d23c #208 0x00007ff3c31a7ec5 #209 0x00007ff3c301ac77 #210 0x00007ff3c357c573 ```` The fix implements two key changes. 1. **Hook functions (`memalloc_alloc`, `memalloc_realloc`)**: Snapshot the allocator struct locally before use and guard indirect function calls with `NULL` checks. This prevents crashes if a partially-written struct is observed during a start/stop race. 2. **Start/stop operations (`memalloc_start`, `memalloc_stop`)**: Use local variables and single assignments when publishing the allocator struct to `global_memalloc_ctx.pymem_allocator_obj`. This ensures concurrent hook calls observe either the old or new struct, never a partially-written intermediate state. The real root cause is that `PyMem_GetAllocator` is not documented as atomic, and the struct could be read field-by-field while being written to concurrently. By using local copies and single assignments, we ensure atomicity at the C level and prevent observation of inconsistent state. Co-authored-by: thomas.kowalski <thomas.kowalski@datadoghq.com>

Raphael Gavache added 5 commits February 10, 2017 15:41

dd-trace-py: client does not properly surface HTTP errors

f488028

adding handle_responde() from dd-trace-rb

dd-trace-py: client does not properly surface HTTP errors

3dd2db1

adding response handling

Merge branch 'raphael/http_agent_request_errors' of github.com:DataDo…

ed4e54e

…g/dd-trace-py into raphael/http_agent_request_errors

Logging the http status code of http reauests towards the agent

5cf1320

agent http request errors

ce816a0

fixing

raphaelgavache requested a review from talwai February 13, 2017 18:00

clutchski reviewed Feb 13, 2017

View reviewed changes

Raphael Gavache and others added 12 commits February 13, 2017 23:11

logging agent http error requests

f174b52

periodically (every 1s)

agent http logging error requests

4a6ac99

small fix

agent http error logging

3e48e47

changing how the the timer works

logging http agent error requests

fe03c91

.stop() already used in python3 threading, changing name

Http request errors log trace.py <-> agent

d4b9924

Using AsyncWorker _target thread function to write the http log requests

Http request errors log trace.py <-> agent

3596678

flake8 fix

logging http error status

57e72fd

log on the Writer

agent http request errors

c9ef6dc

quick fix

Merge remote-tracking branch 'origin/master' into raphael/agent_http_…

ad6043a

…request_errors

agent http error code

47262a3

bad indent fix

logging agent http errors

0b8809a

small fix

agent http error logging test

af729d6

clutchski reviewed Feb 14, 2017

View reviewed changes

Raphael Gavache and others added 3 commits February 14, 2017 18:22

Verification Test IndexErrors should pop intentionally

dce900d

Trying to raise error to check log

2ea822c

Test unit for logging http agent errors

b88bc9f

talwai reviewed Feb 15, 2017

View reviewed changes

Raphael Gavache added 4 commits March 10, 2017 11:18

Merge branch 'raphael/agent_http_request_errors' of github.com:DataDo…

0eb0598

…g/dd-trace-py into raphael/agent_http_request_errors

fixing name of class for tests

df1263f

adding default_hostname/port to flawed api writer

9029740

Correction on logging -> protection with getattr

5b86dc8

palazzem assigned palazzem and talwai Mar 13, 2017

talwai approved these changes Mar 13, 2017

View reviewed changes

Raphael Gavache and others added 2 commits March 13, 2017 15:23

cleaning code, function name error

3270d28

np removing useless space

0ca9d5c

palazzem suggested changes Mar 16, 2017

View reviewed changes

Raphael Gavache added 4 commits March 16, 2017 11:29

Corrections after Manu's review

e8d38b3

Merge branch 'raphael/agent_http_request_errors' of github.com:DataDo…

49764cc

…g/dd-trace-py into raphael/agent_http_request_errors

correction on log name

eae1a88

changing switch to ok_

9be58db

palazzem approved these changes Mar 29, 2017

View reviewed changes

palazzem modified the milestone: 0.8.0 Mar 29, 2017

raphaelgavache merged commit 3ab3525 into master Mar 29, 2017

palazzem deleted the raphael/agent_http_request_errors branch March 30, 2017 13:19

palazzem modified the milestones: 0.8.0, 0.7.1 Apr 3, 2017

palazzem modified the milestones: 0.7.1, 0.8.0 Apr 10, 2017


		time.sleep(1) # replace with a blocking pop.

		# Logging the http errors

Conversation

raphaelgavache commented Feb 13, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Summary

Testing

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

raphaelgavache Feb 14, 2017 • 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!

Choose a reason for hiding this comment

Uh oh!

clutchski Feb 14, 2017 • 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!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

palazzem left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

palazzem Mar 16, 2017 • 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!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

raphaelgavache commented Feb 13, 2017 •

edited

Loading

raphaelgavache Feb 14, 2017 •

edited

Loading

clutchski Feb 14, 2017 •

edited

Loading

palazzem Mar 16, 2017 •

edited

Loading