absence of logs with appengine.monkeypatch()

[euri10]

the below simple flask app displays the requests logs correctly when appengine.monkeypatch() is commented.

I got no logs when it's on however, which sucks because I want to request https stuff

is there something I configured badly, my dev_appserver.py runs with the --log_level=debug switch

correct behaviour

INFO     2018-05-16 13:48:34,256 sdk_update_checker.py:231] Checking for updates to the SDK.
INFO     2018-05-16 13:48:34,450 sdk_update_checker.py:259] The SDK is up to date.
INFO     2018-05-16 13:48:34,575 api_server.py:274] Starting API server at: http://localhost:38997
INFO     2018-05-16 13:48:34,590 dispatcher.py:270] Starting module "default" running at: http://0.0.0.0:8080
INFO     2018-05-16 13:48:34,591 admin_server.py:152] Starting admin server at: http://localhost:8000
pydev debugger: process 17430 is connecting

10
10
DEBUG    2018-05-16 13:48:40,189 connectionpool.py:208] Starting new HTTP connection (1): google.com
send: 'GET / HTTP/1.1\r\nHost: google.com\r\nAccept-Encoding: gzip, deflate\r\nUser-Agent: python-requests/2.18.4\r\nAccept: */*\r\nConnection: keep-alive\r\n\r\n'
reply: 'HTTP/1.1 301 Moved Permanently\r\n'
header: Location: http://www.google.com/
header: Content-Type: text/html; charset=UTF-8
header: Date: Wed, 16 May 2018 13:48:40 GMT
header: Expires: Fri, 15 Jun 2018 13:48:40 GMT
header: Cache-Control: public, max-age=2592000
header: Server: gws
header: Content-Length: 219
header: X-XSS-Protection: 1; mode=block
header: X-Frame-Options: SAMEORIGIN
DEBUG    2018-05-16 13:48:40,249 connectionpool.py:396] http://google.com:80 "GET / HTTP/1.1" 301 219
DEBUG    2018-05-16 13:48:40,257 connectionpool.py:208] Starting new HTTP connection (1): www.google.com
send: 'GET / HTTP/1.1\r\nHost: www.google.com\r\nAccept-Encoding: gzip, deflate\r\nUser-Agent: python-requests/2.18.4\r\nAccept: */*\r\nConnection: keep-alive\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: Date: Wed, 16 May 2018 13:48:40 GMT
header: Expires: -1
header: Cache-Control: private, max-age=0
header: Content-Type: text/html; charset=ISO-8859-1
header: P3P: CP="This is not a P3P policy! See g.co/p3phelp for more info."
header: Content-Encoding: gzip
header: Server: gws
header: Content-Length: 4637
header: X-XSS-Protection: 1; mode=block
header: X-Frame-Options: SAMEORIGIN
header: Set-Cookie: 1P_JAR=2018-05-16-13; expires=Fri, 15-Jun-2018 13:48:40 GMT; path=/; domain=.google.com
header: Set-Cookie: NID=130=k7E95bKF5aobJs9RqT7pv6NkJ0NQMG6dKnIP3PclAPeVd56uRfviRcnugC-vDLAyf2SbQ38ByygVo5EzqatPSOdewigmPbGdaXd_Q29aLG1O9WDDKZNRmHESAfQuFLHT; expires=Thu, 15-Nov-2018 13:48:40 GMT; path=/; domain=.google.com; HttpOnly
DEBUG    2018-05-16 13:48:40,350 connectionpool.py:396] http://www.google.com:80 "GET / HTTP/1.1" 200 4637
INFO     2018-05-16 13:48:40,367 module.py:846] default: "GET /log HTTP/1.1" 200 2

no logs

INFO     2018-05-16 13:50:08,014 sdk_update_checker.py:231] Checking for updates to the SDK.
INFO     2018-05-16 13:50:08,215 sdk_update_checker.py:259] The SDK is up to date.
INFO     2018-05-16 13:50:08,328 api_server.py:274] Starting API server at: http://localhost:35295
INFO     2018-05-16 13:50:08,347 dispatcher.py:270] Starting module "default" running at: http://0.0.0.0:8080
INFO     2018-05-16 13:50:08,349 admin_server.py:152] Starting admin server at: http://localhost:8000
pydev debugger: process 17596 is connecting

/home/ben/PycharmProjects/utmanage/lib/urllib3/contrib/appengine.py:115: AppEnginePlatformWarning: urllib3 is using URLFetch on Google App Engine sandbox instead of sockets. To use sockets directly instead of URLFetch see https://urllib3.readthedocs.io/en/latest/reference/urllib3.contrib.html.
  AppEnginePlatformWarning)
10
10
INFO     2018-05-16 13:50:11,466 module.py:846] default: "GET /log HTTP/1.1" 200 2

simple flask app

import contextlib
import datetime

import requests
from flask import Flask, jsonify, request
from google.appengine.api.app_identity import get_application_id
from google.appengine.ext import ndb
from requests.utils import add_dict_to_cookiejar

import config
import logging
import httplib

httplib.HTTPConnection.debuglevel = 1
logger = logging.getLogger(__name__)
logging.basicConfig()
logger.setLevel(logging.DEBUG)

requests_log = logging.getLogger("requests.packages.urllib3")
requests_log.setLevel(logging.DEBUG)
requests_log.propagate = True

from requests_toolbelt.adapters import appengine

appengine.monkeypatch()

app = Flask(__name__)


@app.route('/log')
def log():
    s = requests.session()
    print(logging.getLogger().getEffectiveLevel())
    print(requests_log.getEffectiveLevel())
    s.get('http://google.com')
    return 'ok', 200

if __name__ == '__main__':
    app.run(host='0.0.0.0', port=8080, debug=True)

[sigmavirus24]

I believe this is because the appengine adapter is just a shim on top of urllib3's support for AppEngine which is a shim for using urlfetch. That means most of the control that urllib3 has (where all of your logs actually come from) is gone. I'm not sure how to further enable that, but I would suggest opening a companion issue against urllib3 for this behaviour.