Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Extrapolating statistics from Cheroot doesn't work #99

Closed
sanitec opened this issue Jun 12, 2018 · 15 comments

Comments

Projects
None yet
4 participants
@sanitec
Copy link

commented Jun 12, 2018

I'm submitting a ...

  • bug report
  • feature request
  • question about the decisions made in the repository

Describe the bug. What is the current behavior?

Getting the following error when trying to extrapolate statistics from Cheroot:
AttributeError: 'BufferedReader' object has no attribute 'bytes_read'

What is the motivation / use case for changing the behavior?
It's broken

To Reproduce

Steps to reproduce the behavior:

  1. Configure Cherrypy to use the following plugin:
import logging

import cherrypy

class CherootStatistics(cherrypy.process.plugins.SimplePlugin):
    def __init__(self, bus):
        super(CherootStatistics, self).__init__(bus)
        self._enabled = False

    def main(self):
        if not self._enabled:
            self.bus.log('Enabling Cheroot statistics')
            for key in logging.statistics.keys():
                if 'Cheroot HTTPServer' in key:
                    logging.statistics[key]['Enabled'] = True
                    break
            self._enabled = True
  1. Mount cpstats to '/cpstats'
  2. Open localhost:8080/cpstats in browser

Expected behavior

To see the beautiful statistics of Cheroot

Details

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/cherrypy/_cprequest.py", line 631, in respond
    self._do_respond(path_info)
  File "/usr/local/lib/python3.6/site-packages/cherrypy/_cprequest.py", line 690, in _do_respond
    response.body = self.handler()
  File "/usr/local/lib/python3.6/site-packages/cherrypy/lib/encoding.py", line 264, in __call__
    ct.params['charset'] = self.find_acceptable_charset()
  File "/usr/local/lib/python3.6/site-packages/cherrypy/lib/encoding.py", line 173, in find_acceptable_charset
    if encoder(self.default_encoding):
  File "/usr/local/lib/python3.6/site-packages/cherrypy/lib/encoding.py", line 114, in encode_string
    for chunk in self.body:
  File "/usr/local/lib/python3.6/site-packages/cherrypy/lib/cpstats.py", line 522, in index
    for title, scalars, collections in self.get_namespaces():
  File "/usr/local/lib/python3.6/site-packages/cherrypy/lib/cpstats.py", line 587, in get_namespaces
    s = extrapolate_statistics(logging.statistics)
  File "/usr/local/lib/python3.6/site-packages/cherrypy/lib/cpstats.py", line 212, in extrapolate_statistics
    v = extrapolate_statistics(v)
  File "/usr/local/lib/python3.6/site-packages/cherrypy/lib/cpstats.py", line 216, in extrapolate_statistics
    v = v(scope)
  File "/usr/local/lib/python3.6/site-packages/cheroot/server.py", line 1529, in <lambda>
    [w['Bytes Read'](w) for w in s['Worker Threads'].values()], 0),
  File "/usr/local/lib/python3.6/site-packages/cheroot/server.py", line 1529, in <listcomp>
    [w['Bytes Read'](w) for w in s['Worker Threads'].values()], 0),
  File "/usr/local/lib/python3.6/site-packages/cheroot/workers/threadpool.py", line 76, in <lambda>
    self.conn.rfile.bytes_read
AttributeError: 'BufferedReader' object has no attribute 'bytes_read'

Environment

  • Cheroot version: 6.3.1
  • CherryPy version: 15.0.0 (if applicable)
  • Python version: 3.6.5
  • OS: MacOS 10.13.x

Additional context

@webknjaz

This comment has been minimized.

Copy link
Member

commented Jun 15, 2018

@sanitec do you have cheroot+cherrypy version combination when it worked?

@sanitec

This comment has been minimized.

Copy link
Author

commented Jun 15, 2018

@webknjaz No, we've only tried with latest versions. It's a feature we're keen to use in our application, but haven't had much luck with Cheroot's statistics.

@webknjaz

This comment has been minimized.

Copy link
Member

commented Jun 15, 2018

It looks like this argument is used to be present in Python 2 implementation, while Python 3 returns BufferedReader from stdlib, which doesn't have this attribute implemented:

self.bytes_read += len(data)

@webknjaz

This comment has been minimized.

Copy link
Member

commented Jun 15, 2018

cc @jaraco we probably need to refactor cheroot.makefile module

@webknjaz

This comment has been minimized.

Copy link
Member

commented Feb 12, 2019

Hey @sanitec, is this still reproducible with current master?

@jshiell

This comment has been minimized.

Copy link

commented Feb 22, 2019

I fear I'm still seeing this issue with Cheroot 6.5.4 on Python 3.6.8 and having to monkey-patch WorkerThread.run to avoid

self.bytes_read += self.conn.rfile.bytes_read
self.bytes_written += self.conn.wfile.bytes_written
@webknjaz

This comment has been minimized.

Copy link
Member

commented Feb 25, 2019

This commit 14bcf2a should probably be cherry-picked to address the current issue...

@jaraco

This comment has been minimized.

Copy link
Member

commented Mar 26, 2019

I could use some help with this issue. Namely, how to replicate it. Instructions say "configure plugin" and "mount cpstats", but I'm not sure how the user might have done that. I could try to figure it out, but it would be nice to have a full reproducer that doesn't require me to make assumptions or code the reproducer.

@jaraco

This comment has been minimized.

Copy link
Member

commented Mar 26, 2019

I created this script to reproduce the issue. I also created the following Dockerfile that will build a server:

FROM python:3

RUN pip install cherrypy

ADD https://gist.githubusercontent.com/jaraco/b67d91b555768bbd7c4001bdc978ce6a/raw/f39d4a95905d69882a3b18fc5209e847f9ee775a/server.py server.py

EXPOSE 8080

CMD python server.py

Just create Dockerfile and then build with docker build . -t cheroot99. Then docker run -p 8080:8080 -it cheroot99. It will launch a server on port 8080. Then, requesting the root page, you get the statistics:

$ http http://localhost:8080                                                                                                                                                 
HTTP/1.1 200 OK
Content-Length: 6858
Content-Type: text/html;charset=utf-8
Date: Tue, 26 Mar 2019 20:20:40 GMT
Server: CherryPy/18.1.0

<html>
<head>
    <title>Statistics</title>
<style>

th, td {
    padding: 0.25em 0.5em;
    border: 1px solid #666699;
}

table {
    border-collapse: collapse;
}

table.stats1 {
    width: 100%;
}

table.stats1 th {
    font-weight: bold;
    text-align: right;
    background-color: #CCD5DD;
}

table.stats2, h2 {
    margin-left: 50px;
}

table.stats2 th {
    font-weight: bold;
    text-align: center;
    background-color: #CCD5DD;
}

</style>
</head>
<body>

<h1>Cheroot HTTPServer 139801399372208</h1>

<table class='stats1'>
    <tbody>

        <tr>
            <th>Accepts</th><td id='Cheroot HTTPServer 139801399372208-Accepts'>0</td>
            <th>Accepts/sec</th><td id='Cheroot HTTPServer 139801399372208-Accepts/sec'>0.0</td>
            <th>Bind Address</th><td id='Cheroot HTTPServer 139801399372208-Bind Address'>('::', 8080)</td>
        </tr>
        <tr>
            <th>Bytes Read</th><td id='Cheroot HTTPServer 139801399372208-Bytes Read'>-1</td>
            <th>Bytes Written</th><td id='Cheroot HTTPServer 139801399372208-Bytes Written'>-1</td>
            <th>Enabled</th><td id='Cheroot HTTPServer 139801399372208-Enabled'>False</td>
        </tr>
        <tr>
            <th>Queue</th><td id='Cheroot HTTPServer 139801399372208-Queue'>0</td>
            <th>Read Throughput</th><td id='Cheroot HTTPServer 139801399372208-Read Throughput'>-1</td>
            <th>Requests</th><td id='Cheroot HTTPServer 139801399372208-Requests'>-1</td>
        </tr>
        <tr>
            <th>Run time</th><td id='Cheroot HTTPServer 139801399372208-Run time'>-1</td>
            <th>Socket Errors</th><td id='Cheroot HTTPServer 139801399372208-Socket Errors'>0</td>
            <th>Threads</th><td id='Cheroot HTTPServer 139801399372208-Threads'>10</td>
        </tr>
        <tr>
            <th>Threads Idle</th><td id='Cheroot HTTPServer 139801399372208-Threads Idle'>9</td>
            <th>Work Time</th><td id='Cheroot HTTPServer 139801399372208-Work Time'>-1</td>
            <th>Write Throughput</th><td id='Cheroot HTTPServer 139801399372208-Write Throughput'>-1</td>
        </tr>
    </tbody>
</table>
<h2>Worker Threads</h2>
<table class='stats2'>
    <thead>
        <tr>
            <th>ID</th>
            <th>Bytes Read</th>
            <th>Bytes Written</th>
            <th>Read Throughput</th>
            <th>Requests</th>
            <th>Work Time</th>
            <th>Write Throughput</th>
        </tr>
    </thead>
    <tbody>
        <tr>
            <td>CP Server Thread-10</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
        </tr>
        <tr>
            <td>CP Server Thread-11</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
        </tr>
        <tr>
            <td>CP Server Thread-12</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
        </tr>
        <tr>
            <td>CP Server Thread-3</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
        </tr>
        <tr>
            <td>CP Server Thread-4</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
        </tr>
        <tr>
            <td>CP Server Thread-5</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
        </tr>
        <tr>
            <td>CP Server Thread-6</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
        </tr>
        <tr>
            <td>CP Server Thread-7</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
        </tr>
        <tr>
            <td>CP Server Thread-8</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
        </tr>
        <tr>
            <td>CP Server Thread-9</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
            <td>0</td>
            <td>0</td>
            <td>0.0</td>
        </tr>
    </tbody>
</table>
<h1>CherryPy Applications</h1>

<table class='stats1'>
    <tbody>

        <tr>
            <th>Bytes Read/Request</th><td id='CherryPy Applications-Bytes Read/Request'>0.000</td>
            <th>Bytes Read/Second</th><td id='CherryPy Applications-Bytes Read/Second'>0.000</td>
            <th>Bytes Written/Request</th><td id='CherryPy Applications-Bytes Written/Request'>0.000</td>
        </tr>
        <tr>
            <th>Bytes Written/Second</th><td id='CherryPy Applications-Bytes Written/Second'>0.000</td>
            <th>Current Requests</th><td id='CherryPy Applications-Current Requests'>0</td>
            <th>Current Time</th><td id='CherryPy Applications-Current Time'>2019-03-26 20:20:40</td>
        </tr>
        <tr>
            <th>Enabled</th><td id='CherryPy Applications-Enabled'>
            <form action="pause" method="POST" style="display:inline">
            <input type="hidden" name="namespace" value="CherryPy Applications" />
            <input type="submit" value="Pause" />
            </form>
            <form action="resume" method="POST" style="display:inline">
            <input type="hidden" name="namespace" value="CherryPy Applications" />
            <input type="submit" value="Resume" disabled="disabled" />
            </form>
            </td>
            <th>Requests/Second</th><td id='CherryPy Applications-Requests/Second'>0.000</td>
            <th>Server Version</th><td id='CherryPy Applications-Server Version'>18.1.0</td>
        </tr>
        <tr>
            <th>Start Time</th><td id='CherryPy Applications-Start Time'>2019-03-26 20:20:33</td>
            <th>Total Bytes Read</th><td id='CherryPy Applications-Total Bytes Read'>0</td>
            <th>Total Bytes Written</th><td id='CherryPy Applications-Total Bytes Written'>0</td>
        </tr>
        <tr>
            <th>Total Requests</th><td id='CherryPy Applications-Total Requests'>0</td>
            <th>Total Time</th><td id='CherryPy Applications-Total Time'>0.000</td>
            <th>Uptime</th><td id='CherryPy Applications-Uptime'>7.203</td>
        </tr>
    </tbody>
</table>
<h2>Requests</h2>
<table class='stats2'>
    <thead>
        <tr>
            <th>ID</th>
        </tr>
    </thead>
    <tbody>
    </tbody>
</table>
</body>
</html>

Everything seems to be working. I seem to be unable to replicate the issue with the latest cherrypy/cheroot.

@jaraco

This comment has been minimized.

Copy link
Member

commented Mar 26, 2019

Hmm. Earlier when I was running the server, I saw the "Enabling Cheroot statistics", which I no longer see, so I don't think the plugin is being activated.

@jaraco

This comment has been minimized.

Copy link
Member

commented Mar 26, 2019

I only sometimes see the message "Enabling Cheroot statistics" and seemingly only when the Autoreloader is triggered and after the engine exits:

[26/Mar/2019:16:45:01] ENGINE Listening for SIGTERM.
[26/Mar/2019:16:45:01] ENGINE Listening for SIGHUP.
[26/Mar/2019:16:45:01] ENGINE Listening for SIGUSR1.
[26/Mar/2019:16:45:01] ENGINE Bus STARTING
[26/Mar/2019:16:45:01] ENGINE Started monitor thread 'Autoreloader'.
[26/Mar/2019:16:45:01] ENGINE Serving on http://::0:8080
[26/Mar/2019:16:45:01] ENGINE Bus STARTED
[26/Mar/2019:16:45:03] ENGINE Restarting because /Users/jaraco/code/public/cherrypy/cheroot/server.py changed.
[26/Mar/2019:16:45:03] ENGINE Stopped thread 'Autoreloader'.
[26/Mar/2019:16:45:03] ENGINE Bus STOPPING
[26/Mar/2019:16:45:03] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('::', 8080)) shut down
[26/Mar/2019:16:45:03] ENGINE Bus STOPPED
[26/Mar/2019:16:45:03] ENGINE Bus EXITING
[26/Mar/2019:16:45:03] ENGINE Bus EXITED
[26/Mar/2019:16:45:03] ENGINE Enabling Cheroot statistics
[26/Mar/2019:16:45:03] ENGINE Waiting for child threads to terminate...
[26/Mar/2019:16:45:03] ENGINE Re-spawning /Library/Frameworks/Python.framework/Versions/3.7/Resources/Python.app/Contents/MacOS/Python server.py
[26/Mar/2019:16:45:04] ENGINE Listening for SIGTERM.
[26/Mar/2019:16:45:04] ENGINE Listening for SIGHUP.
[26/Mar/2019:16:45:04] ENGINE Listening for SIGUSR1.
[26/Mar/2019:16:45:04] ENGINE Bus STARTING
[26/Mar/2019:16:45:04] ENGINE Started monitor thread 'Autoreloader'.
[26/Mar/2019:16:45:04] ENGINE Serving on http://::0:8080
[26/Mar/2019:16:45:04] ENGINE Bus STARTED
@jaraco

This comment has been minimized.

Copy link
Member

commented Mar 26, 2019

Okay, if I grab cherrypy 15.0.0, I see the cheroot statistics get enabled and the 'main' event fires several times per second... so something about cherrypy 18.0.1 has eliminated that main event firing.

@jaraco

This comment has been minimized.

Copy link
Member

commented Mar 26, 2019

Aha, so the issue appears to be in cherrypy/cherrypy@20bc9db. Without that, main only gets called when the state changes, instead of periodically as the docs state it should.

@jaraco jaraco referenced this issue Mar 26, 2019

Merged

publish should be called when the state is changed #1759

10 of 15 tasks complete
@jaraco

This comment has been minimized.

Copy link
Member

commented Mar 27, 2019

After addressing the emergent issue in CherryPy, I've had some success reproducing the issue with this script (use this link in the Dockerfile). Now, when I request / against that server, I see this in the server output:

[27/Mar/2019:09:56:49] ENGINE Listening for SIGTERM.
[27/Mar/2019:09:56:49] ENGINE Listening for SIGHUP.
[27/Mar/2019:09:56:49] ENGINE Listening for SIGUSR1.
[27/Mar/2019:09:56:49] ENGINE Bus STARTING
[27/Mar/2019:09:56:49] ENGINE Started monitor thread 'Autoreloader'.
[27/Mar/2019:09:56:49] ENGINE Serving on http://::0:8080
[27/Mar/2019:09:56:49] ENGINE Bus STARTED
[27/Mar/2019:09:56:49] ENGINE Enabling Cheroot HTTPServer 4478267576 statistics
Exception in thread CP Server Thread-4:
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 917, in _bootstrap_inner
    self.run()
  File "/Users/jaraco/code/public/cherrypy/cheroot/cheroot/workers/threadpool.py", line 119, in run
    self.bytes_read += self.conn.rfile.bytes_read
AttributeError: 'StreamReader' object has no attribute 'bytes_read'

::1 - - [27/Mar/2019:09:56:58] "GET / HTTP/1.1" 200 11 "" "HTTPie/1.0.2"
@jaraco

This comment has been minimized.

Copy link
Member

commented Mar 27, 2019

I've updated the script to support Python 2.7 also and was able to confirm the issue only exists on Python 3.

jaraco added a commit that referenced this issue Mar 27, 2019

Add test_makefile with a couple of tests capturing the expectation th…
…at the MakeFile result has 'bytes_read' and 'bytes_written' properties. Ref #99.

@jaraco jaraco referenced this issue Mar 27, 2019

Merged

Add support for statistics on Python 3. #186

9 of 15 tasks complete

@jaraco jaraco closed this in 16e7691 Mar 27, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.