Packet sequence number wrong (PyMySQL driver or…?)

[jens.t...@gmail.com]

Hello,

I’m using SQLAlchemy (1.1.13) and SQLAlchemy-Utils (0.32.14) in the context of a Pyramid (1.9.1) web-browser, PyMySQL (0.7.11) as a driver, and mysql 5.6.3. I followed the Pyramid/Alchemy Cookiecutter implementation.

On seemingly random requests (although all seem to be OPTIONS) I see the following exception in the server logs (see also this PyMySQL issue):

2017-09-28 18:13:17,765 ERROR [sqlalchemy.pool.QueuePool][b'uWSGIWorker1Core0'] Exception during reset or similar
Traceback (most recent call last):
  File "/var/www/…/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1182, in _execute_context
    context)
  File "/var/www/…/lib64/python3.6/site-packages/sqlalchemy/engine/default.py", line 470, in do_execute
    cursor.execute(statement, parameters)
  File "/var/www/…/lib64/python3.6/site-packages/pymysql/cursors.py", line 166, in execute
    result = self._query(query)
  File "/var/www/…/lib64/python3.6/site-packages/pymysql/cursors.py", line 322, in _query
    conn.query(q)
  File "/var/www/…/lib64/python3.6/site-packages/pymysql/connections.py", line 856, in query
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  File "/var/www/…/lib64/python3.6/site-packages/pymysql/connections.py", line 1057, in _read_query_result
    result.read()
  File "/var/www/…/lib64/python3.6/site-packages/pymysql/connections.py", line 1340, in read
    first_packet = self.connection._read_packet()
  File "/var/www/…/lib64/python3.6/site-packages/pymysql/connections.py", line 1001, in _read_packet
    % (packet_number, self._next_seq_id))
pymysql.err.InternalError: Packet sequence number wrong - got 102 expected 8

I see this error in different variations for the packet sequence. Any hint or tip to explain this issue is appreciated!

Thank you!

Jens

[Mike Bayer]

the log seems to indicate the connection pool has gotten the
connection back and is attempting to emit a rollback() upon it. These
can fail if the connection has already had some varieties of error
occur upon it, most often when the work on the connection was
interrupted, such as when receiving a greenlet or thread exit. It's
likely when a WSGI request is interrupted, the cleanup logic here
fails because the connection has been thrown into an invalid state.
The connection is invalidated (e.g. discarded) in this case and is
harmless.


>
> Thank you!
> Jens
>
> --
> SQLAlchemy -
> The Python SQL Toolkit and Object Relational Mapper
>
> http://www.sqlalchemy.org/
>
> To post example code, please provide an MCVE: Minimal, Complete, and
> Verifiable Example. See http://stackoverflow.com/help/mcve for a full
> description.
> ---
> You received this message because you are subscribed to the Google Groups
> "sqlalchemy" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to sqlalchemy+...@googlegroups.com.
> To post to this group, send email to sqlal...@googlegroups.com.
> Visit this group at https://groups.google.com/group/sqlalchemy.
> For more options, visit https://groups.google.com/d/optout.

[jens.t...@gmail.com]

Thank you, Mike! 

I would have never extracted your interpretation from the trace! (I don’t know the code…) 

The two questions that arise now, though, are

 - Why would connections drop out of the pool, is this a configuration problem that I should worry about?

 - The request still failed with a 502 although, as you said, it’s a harmless exception. What is the proper way of handling these situations?

Still learning new things here, and I’m curious about your suggestions :-)

Jens

[Mike Bayer]

On Thu, Sep 28, 2017 at 7:17 PM, <jens.t...@gmail.com> wrote:
> Thank you, Mike!
>
> I would have never extracted your interpretation from the trace! (I don’t
> know the code…)
>
> The two questions that arise now, though, are
>
> - Why would connections drop out of the pool, is this a configuration
> problem that I should worry about?

something was already wrong with the connection when the pool got it
back, so it had to be discarded. as far as what was wrong, it had to
do with the request itself, and it was very possibly the web request's
client dropped the connection, e.g. user hit the stop button. Not
sure what uswgi does but it might have called a thread.exit() /
SystemExit that interrupted PyMySQL's work on the socket. This is
something we definitely see in the eventlet world at least.

> - The request still failed with a 502 although, as you said, it’s a
> harmless exception. What is the proper way of handling these situations?

if uwsgi is killing off threads when a connection is cut, it might
want to be more graceful about that and at least log that the thread
was killed in the middle. If this is in fact what's going on. I
stick with apache/mod_wsgi for reasons like these.

[jens.t...@gmail.com]

Again, thank you Mike!

I never see these issues happening locally, which is where I use gunicorn as the server. Your theory might explain that. The trace comes from our beta server online, which runs nginx/uwsgi. I'll poke around the configuration, maybe that'll show something.

Eventually though (in the next one-two months) I would like to move to gunicorn as the sole server, because handling API requests is the only thing it needs to do.

Cheers,

Jens

[jens.t...@gmail.com]

After asking at the uWSGI mailing list (see this thread) the suggested solution was to enable the lazy-apps flags. That seems to have worked...

[Mike Bayer]

oh, a "pre fork" problem, does that mean TCP connections to mysql are
being copied from the main process to forked child processes? I
didn't know uwsgi was that kind of server. That would have because
multiple processes sending data on the same filehandle and would also
cause this problem, though I'd think it would be more severe in its
symptoms.

[jens.t...@gmail.com]

I don't know, Mike, perhaps a good question to ask the mailing list?

[Jonathan Vanasco]

@mike - yes, uwsgi is that kind of server. It takes advantage of copy-on-write memory

This sounds like Jens is connecting to the database before it forks (usually any code that isn't wrapped in request logic)

uwsgi has a postfork hook, which can be handled via a decorator (http://uwsgi-docs.readthedocs.io/en/latest/PythonDecorators.html#uwsgidecorators.postfork) or api.

the common way to handle this is with a fixup routine, and `dispose` on each engine (http://docs.sqlalchemy.org/en/latest/core/connections.html#sqlalchemy.engine.Engine.dispose)

    def my_atfork():

        for engine in models.engines:

            engine.dispose()

  

i have a tiny intregration for it under pyramid available on pypi (https://github.com/jvanasco/pyramid_forksafe) , which I only packaged up because we occasionally run things on gunicorn and I maintaining two fixups was annoying.   the key thing to look at is in my uwsgi `container` code (https://github.com/jvanasco/pyramid_forksafe/blob/master/pyramid_forksafe/containers/uwsgi.py) and the try/except with the uwsgidecorators package.  that package is only loaded when you're running under uwsgi - it's not otherwise available in the same python environment.  you need to wrap it in a try/except, otherwise your app won't run under pserve/waitress or any other development framework.