Python3のMySQLで最新の値を取得できないときがあります。

Question

症状

現在Apache上でmod_wsgiを用いたPythonの簡易的なチャットWebアプリのようなものを制作しています。
PythonでMySQLから"select * from chat_log"で全データを取得していますが、 新たに更新したレコードだけ取得できたりできなかったりします。
httpdを再起動するとなおります。

1秒ごとにJQueryのajaxでbottleを通して取得しています。

以下はMysqlから取得時に整形してPythonでhttpdのerror_logにPrintしたものです。

[error_log]
#正常
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [!]Be accssed in /database->, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] Message is Null., referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [#][2018-08-12 01:48:29 GXJC97] old1, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [2018-08-12 01:49:43 GXJC97]  old2, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [2018-08-12 01:51:51 2F9HEG] old3, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [2018-08-12 20:31:01 06UNHG] old4, referer: http://192.168.66.10:8888/
#↓新たに追加されたnew1 new2がちゃんと取得されている。
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [2018-08-12 20:55:17 AN8B84] new1, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [2018-08-12 20:56:00 AN8B84] new2, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] , referer: http://192.168.66.10:8888/

#異常
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [!]Be accssed in /database->, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] Message is Null., referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [#][2018-08-12 01:48:29 GXJC97] old1, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [2018-08-12 01:49:43 GXJC97]  old2, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [2018-08-12 01:51:51 2F9HEG] old3, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [2018-08-12 20:31:01 06UNHG] old4, referer: http://192.168.66.10:8888/
#new1が取得できなかったり...
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [2018-08-12 20:56:00 AN8B84] new2, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] , referer: http://192.168.66.10:8888/

#異常
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [!]Be accssed in /database->, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] Message is Null., referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [#][2018-08-12 01:48:29 GXJC97] old1, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [2018-08-12 01:49:43 GXJC97]  old2, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [2018-08-12 01:51:51 2F9HEG] old3, referer: http://192.168.66.10:8888/
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] [2018-08-12 20:31:01 06UNHG] old4, referer: http://192.168.66.10:8888/
#両方取得できなかったり
[Sun Aug 12 23:29:46 2018] [error] [client 192.168.66.1] , referer: http://192.168.66.10:8888/

構成

Python:3.6.5
bottle:0.12.13
mod_wsgi:4.6.2
httpd:Apache2.2.15(Unix)
CentOS(仮想):6.8
vagrant:2.1.2
windows:10 home

httpdのvirtualhostを使用しています。

コード

以下コードです。

[Python3.6.5]
from urllib.parse import urlparse
import mysql.connector
import sys
import os


#データベース構成
# tableName: chat＿Log
# id            int(11)         not null auto_increment primary key
# userID        varchar(255)
# postTime      datetime
# talkDetail    varchar(255)


plaseDatabase = 'mysql://admin:password@192.168.66.10:3306/sample';
url = urlparse(plaseDatabase)

#ここのデータベースへの接続オブジェクト？を、def returnMessege()内([A]部分)に移すと一応治りますが...
try:
    db = mysql.connector.connect(
        host = '192.168.66.10' or url.hostname,
        port = '3306' or url.port,
        user = 'admin' or url.username,
        password = 'password' or url.password,
        database = 'sample' or url.path[1:],
    )

    if db.is_connected():
        print("Done connected to "+ plaseDatabase)
    else:
        print("Can't connect to "+ plaseDatabase)
except:
    alertPrint("Failure connecting to database")

cur = db.cursor(dictionary=True)
#ここまでです。

@post('/database')
def returnMessege():
    alertPrint("Be accssed in /database->");
    
    #[A]ここです。

    nowTime = datetime.datetime.now()
    nowTime = nowTime.strftime('%Y-%m-%d %H:%M:%S')

    comment = request.forms['comment']
    userId = request.forms['userID']

    if comment != " ":
        #Put comment into Mysql
        try:
            sql = "insert into chat_log (userId,postTime,talkDetail) values(%s,%s,%s)"
            val = (userId, nowTime, comment)
            cur.execute(sql, val)
            db.commit()
        except:
            alertPrint("Can't put to Database.")

    else:
        print("Message is Null.")


    #Get comment from Database
    chatLogCt = ''
    try:
        cur.execute('select * from chat_log')
        d = cur.fetchall()
        #試しにprintでログをとってみたところ、新たに追加したレコードだけが読み取れたり、読み取れなかったりしました。
        for i in range(len(d)):
            chatLogCt += '[' + str(d[i]['postTime']) + ' '
            chatLogCt += d[i]['userID'] + '] '
            chatLogCt += d[i]['talkDetail'] + '\n'
        print("[#]"+chatLogCt)

    except:
        alertPrint("Can't get from Database.")

[adapter.wsgi]
#coding: utf-8
import sys, os
import bottle

dirpath = os.path.dirname(os.path.abspath(__file__))
sys.path.append(dirpath)
os.chdir(dirpath)

import index
application = bottle.default_app()

試したこと・考え

• 一回の処理が重いのかと思いPythonのTimeで計測しましたが、0.001 0.005秒を切る結果でした。
• mysqld.logを確認しましたが、目立ったエラーはありませんでした。
• データベースのテーブルを確認しましたが、特にデータが消えたりということはありませんでした。

今回はログやMySQLのログを見る限り、PythonとMySQL、もしくはmod_wsgiあたりの相性が問題なのかと検索してみましたが特に有益な情報はありませんでした。
MySQLとの接続オブジェクト？(db)をアクセス毎にその都度生成すると直りましたので原因はそこにあるのかと疑っております。

稚拙な説明で申しわけございませんが、回答お願い致します。他に必要な情報がありましたら用意します。
根本的な解決でなくても、他の言語での似たような経験や、〇〇のlogを見てみるといいよなどの情報でも構いません。
ご助力お願いします。

Answer 1

mysql.connector.connectはあまり使ったことがないので、憶測回答になりますが。

＜＜　理由　＞＞
トランザクション分離レベル(isolation level※1)として、READ COMMITTEDを指定していなく、
なおかつDBカーソルをモジュール変数に持って(※2)、db.commit()後にカーソル(トランザクション)を作り直していないからでは。
＜＜　結果　＞＞
リクエスト処理がサーバーで多重化(apache prefork)時に、DBコネクションがもう1個生まれてトランザクション分離レベル(REPEATABLE READ)の影響を受けるのではないかと。
長くなったので2行ぐらいにまとめ。

ブラウザからのリクエストを受けたプロセスが、insertしたプロセスと同一プロセス/スレッドなら表示される。
そうでないならば、モジュール変数でcur = db.cursor(dictionary=True)を行っているため、
トランザクションの分離レベルが(REPEATABLE READ)なためCOMMIT後に新しく開始されたトランザクションという条件を満たさないので、チャットログが表示されない。

ログファイルにプロセスID/スレッドIDを書き出せば動作確認できるかもです。
※未コンパイルコードです。

from threading import get_ident
from os import getpid

alertPrint(f'pid:{getpid()},tid:{get_ident()}')

■参考情報
mysql connector not showing inserted results

※1 ググるキーワードは「mysql connector isolation level」です。
※2 個人的にはモジュール変数に持たず、DB接続はコネクションプールを使用し、クライアントコードはその都度DBにconnnectする形をお勧め致します。
「connector connection pool python 2017」でググると。
Python Database Connection Pooling with MySQL

---

あと考えられる点はAjaxのcacheが残っているとかです。

---

質問の件から外れますが、ORDER BYを指定しないSELECTは結果の順序性を保証しません。
質問文からはインデクスを貼っているのか読み取れませんでしたが、以下のような形に。

-cur.execute('select * from chat_log')
+cur.execute('select * from chat_log order by postTime, userId')

Comments

[hososo]

返信が遅れて申しわけございません。
コネクションプールを試してみようかと思います。
"SELECTは結果の順序性を保証しません。"初めて知りました！助かります。
詳しく回答していただきありがとうございます。

Answer 2

これかな？
つdb.autocommit(True)

Comments

[hososo]

回答ありがとうございます。リンク、autocommitのアドバイス大変参考になりました。
残念ながらdb.autocommit(True)の指定では回復しませんでした。
アドバイスの元色々試した結果、詳細は質問内容に更新させていただきましたが、dbオブジェクトをアクセス毎に生成すると直りましたので原因はそこにあるのかな？と疑っております。
もし何かありましたら些細なことでも構いませんので、お知恵を貸していただけると大変嬉しいです。