"failed_to_send services to agent", when using mysql + msgpack encoder

[rohitpaulk]

• Doesn't happen when using the JSON encoder
• Happens on master and latest on pypi (v0.10.1)

Script:

pip install msgpack
pip install mysqlclient

import logging
import time

import ddtrace
import MySQLdb

logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.DEBUG)

ddtrace.tracer.configure(hostname='localhost', port=8126)
ddtrace.tracer.debug_logging = True
ddtrace.patch(mysqldb=True)

db = MySQLdb.Connect(host='127.0.0.1', user='root')
c = db.cursor()
c.execute("SHOW DATABASES")
print(c.fetchall())

time.sleep(30)  # Wait for the traces to be sent

Logs:

DEBUG:using Msgpack encoder
INFO:patched 1/1 modules (mysqldb)
DEBUG:set_service_info: service:MySQLdb app:MySQLdb type:None
DEBUG:resetting queues. pids(old:None new:43585)
DEBUG:starting flush thread
DEBUG:set_service_info: service:mysql app:mysql type:db
DEBUG:writing 1 spans (enabled:True)
DEBUG:
      name mysql.query
        id 10203369714858928368
  trace_id 3542858260248615964
 parent_id None
   service mysql
  resource SHOW DATABASES
      type sql
     start 1520243708.58
       end 1520243708.6
  duration 0.014575s
     error 0
      tags
           db.user:root
           out.host:127.0.0.1
           out.port:3306
           sql.query:SHOW DATABASES
           system.pid:43585
(list_of_databases_truncated)
DEBUG:reported 1 traces in 0.00806s
DEBUG:reported 2 services
ERROR:failed_to_send services to Agent: HTTP error status 400, reason Bad Request, message Content-Type: text/plain; charset=utf-8
X-Content-Type-Options: nosniff
Date: Mon, 05 Mar 2018 09:55:21 GMT
Content-Length: 15

Logs from trace agent:

2018-03-05 09:55:20 DEBUG (trace_writer.go:122) - Flushing current traces
2018-03-05 09:55:21 ERROR (receiver.go:274) - cannot decode v0.3 services payload: msgp: attempted to decode type "nil" with method for "str"
2018-03-05 09:55:25 DEBUG (sampler.go:119) - *sampler.PriorityEngine: flushed 0 sampled traces out of 0

I think this is related to the fact that the service payload is expected to have both app and app_type defined as non-null values?

[rohitpaulk]

This is the important part:

DEBUG:set_service_info: service:MySQLdb app:MySQLdb type:None
DEBUG:set_service_info: service:mysql app:mysql type:db

Two services are being reported for the same integration. One of them has a None value for type, which is set here. Replacing that call to include type=db would fix this, but I think it'd be better to tackle the root cause (two services being reported).

[0963390788]

Getting the same issue. How do I change the encoder to use JSON?

[palazzem]

@rohitpaulk sure thing, we'll work on it as soon as possible fixing both issues. the type must be reported and only one service must be sent.

@ToastyBiggums you can manually switch back to JSON using the following snippet:

from ddtrace import tracer
from ddtrace.encoding import JSONEncoder

tracer.writer.api._encoder = JSONEncoder()

As you see, you're using an internal attribute (_encoder) so this should be considered only a temporary workaround. In the meantime we're going to address the problem so that you can remove this part.

We'll notify this thread again once one of our engineers is working actively on this issue.

[palazzem]

Just to give more context, the encoder API is not public because msgpack is the preferred encoder that should be used almost all the time. JSON is considered only a fallback, since msgpack is way faster for our clients (Python, Ruby, etc...) and our Trace Agent.

[rohitpaulk]

Thanks, @palazzem. Just wanted to let you know that this isn't really affecting us apart from spamming our error collection system - the core functionality works fine :)

[palazzem]

Cool @rohitpaulk ! The reason why we're giving low priority to this issue is because service reporting is going to be removed from our clients. Since Agent 5.21.1, they're automatically detected. Because it's not happening in the next couple of weeks, probably we're just going to fix this issue :)

Thanks for your feedback!

[rohitpaulk]

Since Agent 5.21.1, they're automatically detected.

@palazzem I see that 5.24.0 of the agent has been released, is this issue fixed in that release?

[palazzem]

Hey @rohitpaulk! Actually we still need to make a fix on the dd-trace-py client. I'll be sure to put some work before the next release.

[palazzem]

Hey @rohitpaulk! We've updated our client code so that it should not be an issue anymore. Can you verify if #468 solves your problem? It's enough a quick check, then I'll merge it for the next 0.12.1 release.

Thank you very much!

[rohitpaulk]

This fixes the problem in my test script 👍.

On our production installation though, I see the same error on master too. I tried removing patches one by one, and looks like this is due to requests.

Test script:

import logging
import time

import ddtrace
import requests

logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.DEBUG)

ddtrace.tracer.configure(hostname='localhost', port=8126)
ddtrace.tracer.debug_logging = True
ddtrace.patch(requests=True)

requests.get('http://google.com')

time.sleep(30)  # Wait for the traces to be sent

Logs:

DEBUG:using Msgpack encoder
DEBUG:set_service_info: service:requests app:None type:None
DEBUG:resetting queues. pids(old:None new:539)
DEBUG:starting flush thread
INFO:patched 1/1 modules (requests)
DEBUG:Starting new HTTP connection (1): google.com
DEBUG:reported 1 services
ERROR:failed_to_send services to Agent: HTTP error status 400, reason Bad Request, message Content-Type: text/plain; charset=utf-8
X-Content-Type-Options: nosniff
Date: Wed, 23 May 2018 11:02:01 GMT
Content-Length: 15

DEBUG:http://google.com:80 "GET / HTTP/1.1" 301 219
DEBUG:Starting new HTTP connection (1): www.google.com
DEBUG:http://www.google.com:80 "GET / HTTP/1.1" 200 5101
DEBUG:writing 1 spans (enabled:True)

[palazzem]

@rohitpaulk perfect, we're going to check other integrations in the meantime. I'll ping you again so we can ship a bugfix release that addresses the issue you are experiencing.

[palazzem]

Hey @rohitpaulk ! can you check that PR too? #471

It should address the requests issue! Also would be great if you can confirm that this was the last issue with the client sending wrong services to the Agent. Thank you!

[rohitpaulk]

This is the last issue :) Thanks! Will wait for the release.

[palazzem]

Great @rohitpaulk ! Closing this issue then since it will be addressed in the next release (this week at this point).

Thank you very much!