Open
Description
I got Blackfire working in a Docker-compose environment in combination with Flask, and the manual probe function.
the first time when I try to analyze my API endpoint it works, but with a second request I'm always getting the following error.
blackfire_1 | 26/05 11:09:43 DEBUG blackfire-agent blackfire-agent 1.35.1 linux amd64 gc 2020-05-13T12:10:04+0000
blackfire_1 | 26/05 11:09:43 DEBUG blackfire-agent Retrieving public keys from API
blackfire_1 | 26/05 11:09:43 DEBUG blackfire-agent Fetching public keys from API
blackfire_1 | 26/05 11:09:43 DEBUG blackfire-agent Sending request GET https://blackfire.io/agent-api/v1/public-keys
blackfire_1 | 26/05 11:09:44 DEBUG blackfire-agent API answered with status code: 200
blackfire_1 | 26/05 11:09:44 DEBUG blackfire-agent Unmarshalled JSON result: &{[{RWSfcPNpzVzuR1cRAkMPmQT9R6z4uHY0d8reTmCKcnaAHmu1csm9jLxZ RWTscN69dTZ4VsxfZ-1yWCHRjXE7oGNm36-vhGGGzpj_u2euuUReKPrry3OntU3W3igfCH2j2oVapXsp7Q129mKA09V0qIlRNQg= 20200819}]}
blackfire_1 | 26/05 11:09:44 DEBUG blackfire-agent Started verification of '1' public keys
blackfire_1 | 26/05 11:09:44 DEBUG blackfire-agent Retrieving specs from the API
blackfire_1 | 26/05 11:09:44 DEBUG blackfire-agent Fetching specs from API
blackfire_1 | 26/05 11:09:44 DEBUG blackfire-agent Sending request GET https://blackfire.io/agent-api/v3/specs
app_1 | 2020-05-26 11:09:44,597 - python-probe - DEBUG - probe.py:562 - Configuration initialized. [{
app_1 | "agent_socket": "tcp://blackfire:8707",
app_1 | "agent_timeout": 0.25,
app_1 | "client_id": "050e1738-e9a6-458f-ada4-251b48b9152f",
app_1 | "client_token": "e8ce4c90abd6a08418081c9b385cbafd87dacf43baa84b3bd11eaa7abeb5aaa0",
app_1 | "endpoint": "https://blackfire.io/",
app_1 | "log_file": "python-probe.log",
app_1 | "log_level": 4,
app_1 | "challenge": "expires=1590494984&userId=050e1738-e9a6-458f-ada4-251b48b9152f&agentIds=9e267eab-cbec-4290-98de-3333c1b946a8%2C-%2Crequest-id-bc246918-2ba0-445d-8201-1c335e18b8e5&profileSlot=00000000-0000-0000-0000-000000000000&collabToken=752518c5-8d39-43ae-a9e5-d400fa489add",
app_1 | "signature": "RWSfcPNpzVzuR1O6-SUaTzEJzuKkWzzYfyTc8dbotP2Wh7qejmjCXzbouNkfDHfytVPI_mmNJdQNkmxDqvJaLTacjK2skzz3BwU%3D",
app_1 | "args_raw": "aggreg_samples=1&flag_memory=1&flag_sessions=1&flag_cpu=0&flag_nw=0",
app_1 | "args": {
app_1 | "aggreg_samples": "1",
app_1 | "flag_memory": "1",
app_1 | "flag_sessions": "1",
app_1 | "flag_cpu": "0",
app_1 | "flag_nw": "0"
app_1 | }
app_1 | }]
app_1 | * Tip: There are .env or .flaskenv files present. Do "pip install python-dotenv" to use them.
app_1 | * Serving Flask app "src.app" (lazy loading)
app_1 | * Environment: production
app_1 | WARNING: This is a development server. Do not use it in a production deployment.
app_1 | Use a production WSGI server instead.
app_1 | * Debug mode: off
app_1 | * Running on http://0.0.0.0:1234/ (Press CTRL+C to quit)
blackfire_1 | 26/05 11:09:44 DEBUG blackfire-agent API answered with status code: 200
blackfire_1 | 26/05 11:09:46 DEBUG blackfire-agent Merging spec from the API and local spec
blackfire_1 | 26/05 11:09:46 DEBUG blackfire-agent New value of DefaultSpec.LastMaxAge: 24h0m0s
blackfire_1 | 26/05 11:09:46 DEBUG blackfire-agent Listening for connections on 'tcp://0.0.0.0:8707'
blackfire_1 | 26/05 11:09:46 DEBUG blackfire-agent Waiting for new connection
app_1 | 2020-05-26 11:09:54,073 - python-probe - DEBUG - probe.py:142 - Connecting to agent at ('blackfire', 8707).
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Accepted new connection (local address: 172.19.0.2:8707, remote address: 172.19.0.3:51626)
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Setting connection write deadline to 2020-05-26 12:09:54.0803256 +0000 UTC m=+3610.971967401
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Setting connection read deadline to 2020-05-26 12:09:54.0808683 +0000 UTC m=+3610.972509101
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Waiting for new connection
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Profiler protocol detected
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent [ab4] Lock already acquired on our behalf profile
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent [ab4] Handling request
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent [ab4] Checking if agents '9e267eab-cbec-4290-98de-3333c1b946a8' are targeted by request serverIDs '9e267eab-cbec-4290-98de-3333c1b946a8,-,request-id-bc246918-2ba0-445d-8201-1c335e18b8e5'
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent [ab4] Verifying request signature
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent starting data verification with 1 keys and data= expires=1590494984&userId=050e1738-e9a6-458f-ada4-251b48b9152f&agentIds=9e267eab-cbec-4290-98de-3333c1b946a8%2C-%2Crequest-id-bc246918-2ba0-445d-8201-1c335e18b8e5&profileSlot=00000000-0000-0000-0000-000000000000&collabToken=752518c5-8d39-43ae-a9e5-d400fa489add
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Verifying signature key= RWSfcPNpzVzuR1cRAkMPmQT9R6z4uHY0d8reTmCKcnaAHmu1csm9jLxZ signature= RWSfcPNpzVzuR1O6-SUaTzEJzuKkWzzYfyTc8dbotP2Wh7qejmjCXzbouNkfDHfytVPI_mmNJdQNkmxDqvJaLTacjK2skzz3BwU=
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent [ab4] Iterating over features [python-50792432]
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent [ab4] Profile 'RWSfcPNpzVzuR1O6-SUaTzEJzuKkWzzYfyTc8dbotP2Wh7qejmjCXzbouNkfDHfytVPI_mmNJdQNkmxDqvJaLTacjK2skzz3BwU=' is full. Notifying the probe.
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent [ab4] Request handled. Error: false. BlackfireYml: false. Timespan: false. ConfigGathering: false, ComposerLock: false Upload: true. Final: true
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Sending to probe response: Continue: false Progress: 100 BlackfireYml: false ComposerLock: false FirstSample: true
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Configuration parsed from Blackfire specs
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent [ab4] Reading graph data
app_1 | 2020-05-26 11:09:54,092 - python-probe - DEBUG - probe.py:244 - Sending hello req. to Agent. ('b'Blackfire-Query: expires=1590494984&userId=050e1738-e9a6-458f-ada4-251b48b9152f&agentIds=9e267eab-cbec-4290-98de-3333c1b946a8%2C-%2Crequest-id-bc246918-2ba0-445d-8201-1c335e18b8e5&profileSlot=00000000-0000-0000-0000-000000000000&collabToken=752518c5-8d39-43ae-a9e5-d400fa489add&signature=RWSfcPNpzVzuR1O6-SUaTzEJzuKkWzzYfyTc8dbotP2Wh7qejmjCXzbouNkfDHfytVPI_mmNJdQNkmxDqvJaLTacjK2skzz3BwU%3D&aggreg_samples=1&flag_memory=1&flag_sessions=1&flag_cpu=0&flag_nw=0\nBlackfire-Probe: python-50792432\nBlackfire-Auth: 9e267eab-cbec-4290-98de-3333c1b946a8:34c295519278f0efee005073a6ceea97d9e678b2fdf240ee945fc63a11d7c921\n\n'')
app_1 | 2020-05-26 11:09:54,103 - python-probe - DEBUG - probe.py:257 - Response received from Agent. (response='status_code=0, args=defaultdict(<class 'list'>, {'Blackfire-Keys': ['2884905616;RWSfcPNpzVzuR1cRAkMPmQT9R6z4uHY0d8reTmCKcnaAHmu1csm9jLxZ'], 'Blackfire-Fn-Args': ['blackfire.probe.add_marker 1', 'requests.sessions.Session.request 3', 'sqlalchemy.engine.base.Connection.execute 2', 'blackfire.middleware._DjangoCursorWrapper.on_query 5']}), status_val=continue=false&first_sample=true')
app_1 | 2020-05-26 11:09:54,111 - python-probe - DEBUG - probe.py:699 - Profile session ended.
app_1 | 2020-05-26 11:09:54,124 - python-probe - DEBUG - probe.py:160 - Agent connection closed.
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent [ab4] Releasing lock on profile
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent [ab4] Closing connection
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent [ab4] Aggregating graph
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Header: file-format BlackfireProbe
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Header: probed-runtime CPython 3.7.7+Linux-4.19.76-linuxkit-x86_64-with-debian-10.4
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Header: probed-language python
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Header: probed-os Linux-4.19.76-linuxkit-x86_64-with-debian-10.4
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Header: probe-version 1.4.0
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Header: request-sys-load-avg 0.03 0.03 0.02
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Header: probed-features aggreg_samples=1&flag_memory=1&flag_sessions=1&flag_cpu=0&flag_nw=0
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Header: request-start 1590491394.0735092
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Header: request-end 1590491394.1217382
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Header: profile-title unnamed profile
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Header: context script=%2Fusr%2Flocal%2Fbin%2Fpython&argv%5B%5D=run_dev_app.py
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent [ab4] Tag graph.
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent [ab4] Transform graph.
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent [ab4] Uploading profile.
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Posting profile 'RWSfcPNpzVzuR1O6-SUaTzEJzuKkWzzYfyTc8dbotP2Wh7qejmjCXzbouNkfDHfytVPI_mmNJdQNkmxDqvJaLTacjK2skzz3BwU=' to Blackfire API
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Profile payload size is 5.93KB.
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Compressed profile payload size is 1.54KB.
blackfire_1 | 26/05 11:09:54 DEBUG blackfire-agent Sending request POST https://blackfire.io/agent-api/v1/profile-slots/00000000-0000-0000-0000-000000000000
app_1 | 172.19.0.1 - - [26/May/2020 11:09:54] "GET / HTTP/1.1" 200 -
app_1 | 2020-05-26 11:10:00,397 - python-probe - DEBUG - probe.py:142 - Connecting to agent at ('blackfire', 8707).
blackfire_1 | 26/05 11:10:00 DEBUG blackfire-agent Accepted new connection (local address: 172.19.0.2:8707, remote address: 172.19.0.3:51632)
blackfire_1 | 26/05 11:10:00 DEBUG blackfire-agent Setting connection write deadline to 2020-05-26 12:10:00.4036884 +0000 UTC m=+3617.329259301
blackfire_1 | 26/05 11:10:00 DEBUG blackfire-agent Setting connection read deadline to 2020-05-26 12:10:00.4038938 +0000 UTC m=+3617.329470701
blackfire_1 | 26/05 11:10:00 DEBUG blackfire-agent Waiting for new connection
app_1 | 2020-05-26 11:10:00,411 - python-probe - DEBUG - probe.py:244 - Sending hello req. to Agent. ('b'Blackfire-Query: expires=1590494984&userId=050e1738-e9a6-458f-ada4-251b48b9152f&agentIds=9e267eab-cbec-4290-98de-3333c1b946a8%2C-%2Crequest-id-bc246918-2ba0-445d-8201-1c335e18b8e5&profileSlot=00000000-0000-0000-0000-000000000000&collabToken=752518c5-8d39-43ae-a9e5-d400fa489add&signature=RWSfcPNpzVzuR1O6-SUaTzEJzuKkWzzYfyTc8dbotP2Wh7qejmjCXzbouNkfDHfytVPI_mmNJdQNkmxDqvJaLTacjK2skzz3BwU%3D&aggreg_samples=1&flag_memory=1&flag_sessions=1&flag_cpu=0&flag_nw=0\nBlackfire-Probe: python-50792432\nBlackfire-Auth: 9e267eab-cbec-4290-98de-3333c1b946a8:34c295519278f0efee005073a6ceea97d9e678b2fdf240ee945fc63a11d7c921\n\n'')
blackfire_1 | 26/05 11:10:00 DEBUG blackfire-agent Profiler protocol detected
blackfire_1 | 26/05 11:10:00 ERROR blackfire-agent [6b7] Error while acquiring profile: This profile is in a tomb
blackfire_1 | 26/05 11:10:00 DEBUG blackfire-agent Sending error to probe: 206 Buffer already full
blackfire_1 | 26/05 11:10:00 DEBUG blackfire-agent [6b7] Notifying error to listeners: This profile is in a tomb
blackfire_1 | 26/05 11:10:00 DEBUG blackfire-agent [6b7] Closing connection
app_1 | [2020-05-26 11:10:00,418] ERROR in app: Exception on / [GET]
app_1 | Traceback (most recent call last):
app_1 | File "/usr/local/lib/python3.7/site-packages/flask/app.py", line 2447, in wsgi_app
app_1 | response = self.full_dispatch_request()
app_1 | File "/usr/local/lib/python3.7/site-packages/flask/app.py", line 1952, in full_dispatch_request
app_1 | rv = self.handle_user_exception(e)
app_1 | File "/usr/local/lib/python3.7/site-packages/flask/app.py", line 1821, in handle_user_exception
app_1 | reraise(exc_type, exc_value, tb)
app_1 | File "/usr/local/lib/python3.7/site-packages/flask/_compat.py", line 39, in reraise
app_1 | raise value
app_1 | File "/usr/local/lib/python3.7/site-packages/flask/app.py", line 1950, in full_dispatch_request
app_1 | rv = self.dispatch_request()
app_1 | File "/usr/local/lib/python3.7/site-packages/flask/app.py", line 1936, in dispatch_request
app_1 | return self.view_functions[rule.endpoint](**req.view_args)
app_1 | File "/app/src/app.py", line 18, in index
app_1 | probe.enable()
app_1 | File "/usr/local/lib/python3.7/site-packages/blackfire/probe.py", line 616, in enable
app_1 | raise e # re-raise
app_1 | File "/usr/local/lib/python3.7/site-packages/blackfire/probe.py", line 613, in enable
app_1 | _agent_conn.connect()
app_1 | File "/usr/local/lib/python3.7/site-packages/blackfire/probe.py", line 151, in connect
app_1 | self._write_prolog()
app_1 | File "/usr/local/lib/python3.7/site-packages/blackfire/probe.py", line 252, in _write_prolog
app_1 | (self.agent_response)
app_1 | blackfire.exceptions.BlackfireApiException: Invalid response received from Agent. [status_code=1, args=defaultdict(<class 'list'>, {}), status_val=206 Buffer already full]
app_1 | 172.19.0.1 - - [26/May/2020 11:10:00] "GET / HTTP/1.1" 500 -
Docker-compose with:
- python:3.8.1 image
Flask==1.1.2
blackfire==1.3.4
- backfire image
I got the same results in a minimal Flask template using Python 3.7
Metadata
Assignees
Labels
No labels
Activity