Duplicate engineio logs when logging.basicConfig is set

[theahura]

Describe the bug
When I set up default logging using a logging basicConfig, and enable engineio logging, I get duplicate logs.

To Reproduce
Here is a minimal reproduction.

server.py:

import logging
from flask import Flask, render_template
from flask_socketio import SocketIO

# Set up our logger so that it has a good default format and shows all logs.
LOG_FORMAT = ('[%(asctime)s] %(levelname)s p%(process)s %(name)s '
              '[%(pathname)s.%(funcName)s:%(lineno)d] %(message)s')
logging.basicConfig(level=logging.INFO,
                    format=LOG_FORMAT,
                    datefmt="%d/%b/%Y %H:%M:%S",
                    force=True)

# Set up Flask.
app = Flask(__name__, template_folder='frontend/', static_folder='frontend/')

socketio = SocketIO(logger=False, engineio_logger=True)


@app.route('/', methods=['GET'])
def index():
  return render_template('index.html')


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

and frontend/index.html:

<script
  src="https://cdnjs.cloudflare.com/ajax/libs/socket.io/4.0.1/socket.io.js"
  integrity="sha512-q/dWJ3kcmjBLU4Qc47E4A9kTB4m3wuTY7vkFJDTZKjTs8jhyGQnaUrxa0Ytd0ssMZhbNua9hE+E7Qv1j+DyZwA=="
  crossorigin="anonymous"
></script>

<script type="text/javascript">
  var socket = io();
</script>

Expected behavior
I expect to see logs for ping/pong requests appear once, in the format laid out by the basicConfig:

[30/Jun/2021 20:08:01] INFO p2550955 engineio.server [/home/amol/code/soot/logging_flasksocket_test/env/lib/python3.8/site-packages/engineio/socket.py.send:89] Fz37KrSWQMbYNDXeAAAG: Sending packet PING data None
[30/Jun/2021 20:08:01] INFO p2550955 engineio.server [/home/amol/code/soot/logging_flasksocket_test/env/lib/python3.8/site-packages/engineio/socket.py.receive:52] Fz37KrSWQMbYNDXeAAAG: Received packet PONG data 

Instead, I get them twice. Once with the appropriate logging configuration, once without.

Fz37KrSWQMbYNDXeAAAG: Sending packet PING data None
[30/Jun/2021 20:08:01] INFO p2550955 engineio.server [/home/amol/code/soot/logging_flasksocket_test/env/lib/python3.8/site-packages/engineio/socket.py.send:89] Fz37KrSWQMbYNDXeAAAG: Sending packet PING data None
Fz37KrSWQMbYNDXeAAAG: Received packet PONG data 
[30/Jun/2021 20:08:01] INFO p2550955 engineio.server [/home/amol/code/soot/logging_flasksocket_test/env/lib/python3.8/site-packages/engineio/socket.py.receive:52] Fz37KrSWQMbYNDXeAAAG: Received packet PONG data 

This isn't an issue when it's just ping/pong logs, but with very large requests this can rapidly pollute the logging space. Disabling the basic config 'fixes' the issue, but obviously I would like the basic configuration to apply to my logs.

Any guess as to whats going on?

[miguelgrinberg]

The logger=True option in SocketIO does not know what other logging configuration you have. In this case you have created the "global" style configuration in which a handler is attached to the root logger. What you should do if you want to have this type of global configuration is to pass your own logger to Socket.IO:

engineio_logger = logging.getLogger('engineio')
socketio = SocketIO(logger=False, engineio_logger=engineio_logger)