Transactions not working as expected (metrics are not sent)

[raul3z]

How do you use Sentry?

Sentry Saas (sentry.io)

Version

1.26.0; 1.44.1

Steps to Reproduce

Run this script

Expected Result

Having seven entries in sentry Discover, from Sherlock.1 to Sherlock.6 and another one for Holmes

Actual Result

Not having all the metrics, sometimes it works and sometimes not, even with traces_sample_rate set to 1.0 and flushing transactions manually.

output log:
Hello Sherlock.1!
[sentry] DEBUG: Setting up integrations (with default = False)
[sentry] DEBUG: Setting up previously not enabled integration atexit
[sentry] DEBUG: Enabling integration atexit
[sentry] DEBUG: Setting SDK name to 'sentry.python'
[sentry] DEBUG: [Tracing] Starting transaction <Sherlock.1>
[sentry] DEBUG: [Profiling] Discarding profile because profiler was not started.
[sentry] DEBUG: Flushing HTTP transport
[sentry] DEBUG: background worker got flush request
[sentry] DEBUG: background worker flushed
[sentry] DEBUG: [Tracing] Starting transaction <Sherlock.2>
[sentry] DEBUG: [Profiling] Discarding profile because profiler was not started.
Hello Sherlock.2!
[sentry] DEBUG: Flushing HTTP transport
[sentry] DEBUG: Sending envelope [envelope with 1 items (transaction)] project:4505... host:o450...
[sentry] DEBUG: background worker got flush request
[sentry] DEBUG: 2 event(s) pending on flush
[sentry] DEBUG: background worker flushed
[sentry] DEBUG: [Tracing] Starting transaction <Sherlock.3>
[sentry] DEBUG: [Profiling] Discarding profile because profiler was not started.
Hello Sherlock.3!
[sentry] DEBUG: Flushing HTTP transport
[sentry] DEBUG: Sending envelope [envelope with 1 items (transaction)] project:4505... host:o450...
[sentry] DEBUG: background worker got flush request
[sentry] DEBUG: background worker flushed
[sentry] DEBUG: [Tracing] Starting transaction <Sherlock.4>
[sentry] DEBUG: [Profiling] Discarding profile because profiler was not started.
Hello Sherlock.4!
[sentry] DEBUG: Flushing HTTP transport
[sentry] DEBUG: Sending envelope [envelope with 1 items (transaction)] project:4505... host:o450...
[sentry] DEBUG: background worker got flush request
[sentry] DEBUG: background worker flushed
[sentry] DEBUG: [Tracing] Starting transaction <Sherlock.5>
[sentry] DEBUG: [Profiling] Discarding profile because profiler was not started.
Hello Sherlock.5!
[sentry] DEBUG: Sending envelope [envelope with 1 items (transaction)] project:4505... host:o450...
[sentry] DEBUG: Flushing HTTP transport
[sentry] DEBUG: background worker got flush request
[sentry] DEBUG: background worker flushed
[sentry] DEBUG: [Tracing] Starting transaction <Sherlock.6>
[sentry] DEBUG: [Profiling] Discarding profile because profiler was not started.
Hello Sherlock.6!
[sentry] DEBUG: Sending envelope [envelope with 1 items (transaction)] project:4505... host:o450...
[sentry] DEBUG: Flushing HTTP transport
[sentry] DEBUG: background worker got flush request
[sentry] DEBUG: background worker flushed
[sentry] DEBUG: [Tracing] Starting transaction
[sentry] DEBUG: [Profiling] Discarding profile because profiler was not started.
Hello Holmes!
[sentry] DEBUG: Sending envelope [envelope with 1 items (transaction)] project:4505... host:o450...
[sentry] DEBUG: Flushing HTTP transport
[sentry] DEBUG: background worker got flush request
[sentry] DEBUG: background worker flushed
[sentry] DEBUG: atexit: got shutdown signal
[sentry] DEBUG: atexit: shutting down client
[sentry] DEBUG: Flushing HTTP transport
[sentry] DEBUG: Sending envelope [envelope with 1 items (transaction)] project:4505... host:o450...
[sentry] DEBUG: background worker got flush request
[sentry] DEBUG: background worker flushed
[sentry] DEBUG: Killing HTTP transport
[sentry] DEBUG: background worker got kill request
[sentry] DEBUG: Killing HTTP transport

[sentrivana]

Hey @raul3z, thanks for reporting and for providing a script to repro!

I can't reproduce this locally, I get Sherlocks 1 through 6 as well as the Holmes transaction, tried this about 5 times.

Stuff that comes to mind:

1. You write that it sometimes works and sometimes not, what's the rough ratio? Mostly works? Mostly doesn't? 50/50?
2. Is it always the same transactions missing (the first two)?
3. I see you're disabling default integrations other than atexit, does this also happen if you remove that?
4. What Python version are you on?
5. Are you also observing this on bigger scale?

You selected that you're on SaaS -- if you give me your org name I can take a closer look. (You can also send it to me on ivana.kellyerova @ sentry.io if you prefer that.)

[raul3z]

Hi @sentrivana , thank you for answering me!

1. I would say that it mostly does not work.
2. No, it is random
3. Yes, even worst. If I disable atexit the main process finished before metrics could be sent, I tried this morning disabling it and removing manual flushing and no one reached the server. After that I have set manual flush and tried again, then only 3 out of 7 metrics reached the server.
4. I am using python 2.7 but I also have tried with python 3.7, same results here.
5. The problem arose in some parts of our code, this script tries to isolate what is happening. The thing is that we usually use a low sampling rate, so not all metric reach the server (which is normal), in this case I have set the sampling rate to 1.0 to test is properly.

Thanks for your time.
Let me check if I can provide you the org name.

[sentrivana]

Thanks for the follow up!

For 3. I could've worded the question better -- I meant if you still observe this even if you remove default_integrations=False, so basically if you enable all default integrations. You need atexit at least for sure so that the SDK intercepts the interpreter shutting down and forces a flush of any pending events. Can you try and see if anything changes if you enable all default integrations?

[raul3z]

Oh sorry, I misunderstood it.

Yes, I just have tried setting default_integrations=True. Same result flushing or nor manually.

For the org name, what do you need exactly? the company site url or the project DSN?

[sl0thentr0py]

@raul3z you're calling a hub.flush within the start_transaction context manager and the transaction finishes and gets queued to the worker once the context manager exits so that flush will have weird behaviour. Please try this instead.

def send_transaction(name):
    """ Send a Sentry transaction """
    with sentry_sdk.start_transaction(name=name, op='test') as transaction:
        hello(name)


def main():
    """ Main function """
    init_sentry()
    for i in range(6):
        send_transaction('Sherlock.{}'.format(i + 1))
    send_transaction('Holmes')
    sentry_sdk.flush()   # not really necessary since atexit will call this anyway

[raul3z]

That seems to work!

I am receiving the seven entries in Sentry, even if I disable the atexit integration, so for any reason that integration is not working well for us.

[sl0thentr0py]

ok to clarify

you can either disable atexit and flush manually:

def init_sentry():
    """ Initializes Sentry """
    sentry_sdk.init(
        debug=True,
        dsn=DSN,
        max_breadcrumbs=100,
        environment=os.environ.get('ENVIRON'),
        traces_sample_rate=1.0,
        default_integrations=False,
        integrations=[],
    )
    sentry_sdk.set_user({'username': getpass.getuser()})


def main():
    """ Main function """
    init_sentry()
    for i in range(6):
        send_transaction('Sherlock.{}'.format(i + 1))
    send_transaction('Holmes')
    sentry_sdk.flush()

or have atexit and not call flush manually:

def init_sentry():
    """ Initializes Sentry """
    sentry_sdk.init(
        debug=True,
        dsn=DSN,
        max_breadcrumbs=100,
        environment=os.environ.get('ENVIRON'),
        traces_sample_rate=1.0,
        default_integrations=False,
        integrations=[AtexitIntegration()],
    )
    sentry_sdk.set_user({'username': getpass.getuser()})


def main():
    """ Main function """
    init_sentry()
    for i in range(6):
        send_transaction('Sherlock.{}'.format(i + 1))
    send_transaction('Holmes')

these should both do the same thing. In general, you don't need to flush manually anywhere if you just use the sdk with default integrations, stuff should just work.

[raul3z]

It works flushing manually otherwise it does not send all the metrics

[sl0thentr0py]

ok well then just add the flush if that works for you. In theory the flush should happen automatically but maybe there's some other problem with your setup.

[raul3z]

Hi @sl0thentr0py,

I have to say that it is working for my isolated script but if I try to do the same in the main code it is not working, I have to check if we have something wrong there with our code but in the meantime, do you have an idea of what could be wrong? what is the recommended setup?

Thanks!

[sl0thentr0py]

maybe you're killing the process with another signal and the process doesn't get enough time to flush? just a hunch

[raul3z]

I have to check the code properly, just to know, do you have an example on how the server should be initialized? not sure if what I'm doing here is good enough.

[sl0thentr0py]

yes that looks ok to me
you can even simplify and just use the default default_integrations=True (on by default) unless there's something you want to turn off particularly

[raul3z]

Hi there!

After get deeper on this I was not able to make it works for our main script, in fact I tested again the isolated script with the changes that worked and now it is not working again, we cannot dedicate more effort on this so we will assume that we are going to lost some transactions :(

If you have any idea of what could be happening, it is welcome.

Thanks!