classification
Title: XMLRPC behaves strangely under pythonw, not under python
Type: behavior Stage:
Components: Windows Versions: Python 3.8
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: paul.moore, steve.dower, tim.golden, tim_magee, zach.ware
Priority: normal Keywords:

Created on 2021-03-01 04:16 by tim_magee, last changed 2021-03-01 16:06 by tim_magee.

Messages (3)
msg387837 - (view) Author: Tim Magee (tim_magee) Date: 2021-03-01 04:16
Summary: I run a SimpleXMLRPCServer in pythonw. When I call an exposed function the call appears to be made twice and the connection ends abnormally.

This is Python 3.8.3 Windows 64-bit, with the pywin32 additions, and under Windows 7. Boo, hiss, I know -- I won't have access to a win10 machine for a week or so, but I get the impression that that won't affect this behaviour, and the post-3.8.3 changelog doesn't have anything that (to me) looks relevant in it.

I've made a small reproduction that will run on one Windows machine.
You need two small source files (see below):
  * demosrv.py - the server
  * democli.py - the client
The method, in a CMD window:
  * run: start "demosrv" python demosrv.py
    [ runs in its own console window ]
  * run: python democli.py
    [ one instance of notepad appears and the client exits normally ]
  * Ctrl+C in the demosrv window to stop that
  * run: pythonw demosrv.py
    [ runs in background ]
  * run: python democli.py
    [ TWO notepad instances pop up ]
    [ the client crashes with an unexpected connection ]
I've pasted in the two files and an example session below.

This is very much cut-down from the original.  Before deciding to submit I used logging at the top of the exposed function, which appeared to show it being called twice.  Logging immediately before the call in the client showed only one call.

Thanks,
Tim

#--------------8<---- demosrv.py ----8<------------------------------
from xmlrpc.server import SimpleXMLRPCServer
from subprocess import Popen, DEVNULL

def notepad_me():
    try:
        cmd = ['c:\\windows\\notepad.exe']
        p = Popen(cmd, stdin=DEVNULL, stdout=DEVNULL, stderr=DEVNULL)
        return True
    except Exception as e:
        return False

class NetServer(SimpleXMLRPCServer):
    def __init__(self, address):
        super(NetServer, self).__init__(address)
        self.register_introspection_functions()
        self.register_function(notepad_me)

with NetServer(("0.0.0.0", 7777)) as server:
    server.serve_forever()

#---------------8<---- democli.py ----8<-----------------------------
import sys
from xmlrpc.client import ServerProxy, Error

def go():
    try:
        with ServerProxy("http://localhost:7777/") as proxy:
            if proxy.notepad_me():
                return 0
    except Error as e:
        pass
    return 1
sys.exit(go())
#--------------------------------------------------------------------
d:\temp\demo>REM Run the server under python.exe

d:\temp\demo>start "demosrv" python demosrv.py
d:\temp\demo>python democli.py

d:\temp\demo>REM That ran up one instance of notepad
d:\temp\demo>REM Ctrl+C to break out the running demosrv.py

d:\temp\demo>pythonw demosrv.py
d:\temp\demo>REM that runs in the background

d:\temp\demo>python democli.py
Traceback (most recent call last):
  File "democli.py", line 13, in <module>
    sys.exit(go())
  File "democli.py", line 7, in go
    if proxy.notepad_me():
  File "C:\Python\lib\xmlrpc\client.py", line 1109, in __call__
    return self.__send(self.__name, args)
  File "C:\Python\lib\xmlrpc\client.py", line 1450, in __request
    response = self.__transport.request(
  File "C:\Python\lib\xmlrpc\client.py", line 1153, in request
    return self.single_request(host, handler, request_body, verbose)
  File "C:\Python\lib\xmlrpc\client.py", line 1166, in single_request
    resp = http_conn.getresponse()
  File "C:\Python\lib\http\client.py", line 1332, in getresponse
    response.begin()
  File "C:\Python\lib\http\client.py", line 303, in begin
    version, status, reason = self._read_status()
  File "C:\Python\lib\http\client.py", line 272, in _read_status
    raise RemoteDisconnected("Remote end closed connection without"
http.client.RemoteDisconnected: Remote end closed connection without response

d:\temp\demo>REM as you see that ran amok
d:\temp\demo>REM and it created two instances of notepad
msg387867 - (view) Author: Tim Magee (tim_magee) Date: 2021-03-01 14:16
Fragment more info.  First a typo in the description, at the end of the MTR "unexpected connection" should read "unexpected disconnection" of course (no-one expects the unexpected connection ho ho).

Looking at calls to socket functions, Procmon shows the client repeating the call to a server running in pythonw.exe. It seems as though the client is instigating the badness, but...

In a Wireshark capture each of the two sessions the client holds with that 'bad' server is identical, and the difference between each of those and the 'good' session (with the server in python.exe) is that the server under pythonw doesn't return a methodResponse packet, but instead begins tearing down the connection.  Which is what the exception message says, but it's still startling to see it actually happening.

I'll have a squint at the source.
msg387876 - (view) Author: Tim Magee (tim_magee) Date: 2021-03-01 16:06
After a peep at the source I theorised that using logRequests=False when constructing the base class, SimpleXMLRPCServer. would see me right, and so it did.

When logRequests is True control ultimately passes to BaseHTTPRequestHandler.log_message which is a write to sys.stderr, meaning the code is unsuitable for running under pythonw.

This might be a special sort of https://bugs.python.org/issue38533 -- special because the code that offends pythonw is in the library.

Anyhow, now I know what the problem is I can work round it, and I'll leave it to you what to do with the ticket.
History
Date User Action Args
2021-03-01 16:06:50tim_mageesetmessages: + msg387876
2021-03-01 14:16:58tim_mageesetmessages: + msg387867
2021-03-01 04:16:18tim_mageecreate