Deadlock found when trying to get lock

In diesem Forum können Fragen zum OrderSprinter gestellt werden.
misery
Beiträge: 36
Registriert: Do 24. Sep 2020, 09:53

Deadlock found when trying to get lock

Beitrag von misery »

Moin Stefan,

seit heute ist die 2.0.5 mit TSE produktiv geschaltet und der erste Fehler ist aufgetreten.

Der Kellner hat einige Artikel ausgewählt und dann "Arbeitsbon" gedrückt. Dann kam im Browser folgende Meldung.
photo_2020-09-27_15-08-57.jpg
photo_2020-09-27_15-08-57.jpg (121.88 KiB) 4774 mal betrachtet
Auf dem Server ist folgendes im Log.

Code: Alles auswählen

2020/09/27 15:08:28 [error] 48558#48558: *132432 FastCGI sent in stderr: "PHP message: PHP Fatal error:  Uncaught PDOException: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction in /opt/www/webapp/php/commonutils.php:334
Stack trace:
#0 /opt/www/webapp/php/commonutils.php(334): PDOStatement->execute()
#1 /opt/www/webapp/php/utilities/operations.php(42): CommonUtils::execSql()
#2 /opt/www/webapp/php/queuecontent.php(1447): Operations::createOperation()
#3 /opt/www/webapp/php/queuecontent.php(1368): QueueContent::signAtTSE()
#4 /opt/www/webapp/php/queuecontent.php(1125): QueueContent->addProductListToQueueCore()
#5 /opt/www/webapp/php/queuecontent.php(76): QueueContent->addProductListToQueue()
#6 /opt/www/webapp/php/contenthandler.php(65): QueueContent->handleCommand()
#7 {main}
  thrown in /opt/www/webapp/php/commonutils.php on line 334" while reading response header from upstream, client: 192.168.178.20, server: kasse, request: "POST /php/contenthandler.php?module=queue&command=addProductListToQueue HTTP/1.1", upstream: "fastcgi://unix:/run/php/php-fpm.sock:", host: "krusty", referrer: "https://krusty/waiter.html?v=2.0.5"
 

Im access.log ist dies:

Code: Alles auswählen

192.168.178.20 - - [27/Sep/2020:15:07:43 +0200] "GET /img/higher.png HTTP/1.1" 200 2271 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
127.0.0.1 - - [27/Sep/2020:15:07:44 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1510907 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:07:45 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456342 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:07:45 +0200] "GET /php/contenthandler.php?module=queue&command=getJsonLongNamesOfProdsForTableNotDelivered&tableid=19&_=1601211883111 HTTP/1.1" 200 33 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:07:45 +0200] "GET /img/gray.png?t=1601212055759 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:07:46 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
192.168.178.20 - - [27/Sep/2020:15:07:47 +0200] "GET /img/gray.png?t=1601212057689 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
127.0.0.1 - - [27/Sep/2020:15:07:48 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1510953 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:07:48 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456342 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:07:48 +0200] "GET /php/contenthandler.php?module=admin&command=isPrinterServerActive&_=1601211883112 HTTP/1.1" 200 75 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:07:49 +0200] "GET /img/gray.png?t=1601212059688 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:07:49 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:07:51 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1510999 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:07:51 +0200] "GET /img/gray.png?t=1601212061689 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
127.0.0.1 - - [27/Sep/2020:15:07:51 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:07:52 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
192.168.178.20 - - [27/Sep/2020:15:07:53 +0200] "GET /php/contenthandler.php?module=products&command=getAllTypesAndAvailProds&_=1601211883113 HTTP/1.1" 200 6123 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:07:53 +0200] "GET /php/contenthandler.php?module=admin&command=getDailycode&_=1601211883114 HTTP/1.1" 200 53 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:07:53 +0200] "GET /img/gray.png?t=1601212063691 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:07:53 +0200] "GET /php/contenthandler.php?module=admin&command=isPrinterServerActive&_=1601211883115 HTTP/1.1" 200 75 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
127.0.0.1 - - [27/Sep/2020:15:07:54 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511045 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:07:54 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456342 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:07:55 +0200] "GET /img/gray.png?t=1601212065688 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:07:55 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
192.168.178.20 - - [27/Sep/2020:15:07:57 +0200] "GET /img/gray.png?t=1601212067688 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
127.0.0.1 - - [27/Sep/2020:15:07:57 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511091 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:07:58 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:07:58 +0200] "GET /php/contenthandler.php?module=admin&command=isPrinterServerActive&_=1601211883116 HTTP/1.1" 200 75 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:07:58 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
192.168.178.20 - - [27/Sep/2020:15:07:59 +0200] "GET /img/gray.png?t=1601212069743 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
127.0.0.1 - - [27/Sep/2020:15:08:01 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511137 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:08:01 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456342 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:01 +0200] "GET /img/gray.png?t=1601212071687 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:01 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
192.168.178.20 - - [27/Sep/2020:15:08:03 +0200] "GET /php/contenthandler.php?module=admin&command=getDailycode&_=1601211883117 HTTP/1.1" 200 53 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:03 +0200] "GET /img/gray.png?t=1601212073693 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:03 +0200] "GET /php/contenthandler.php?module=admin&command=isPrinterServerActive&_=1601211883118 HTTP/1.1" 200 75 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
127.0.0.1 - - [27/Sep/2020:15:08:04 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511183 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:08:04 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456342 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:05 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
192.168.178.20 - - [27/Sep/2020:15:08:05 +0200] "GET /img/gray.png?t=1601212075689 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:06 +0200] "GET /php/contenthandler.php?module=queue&command=getJsonLongNamesOfProdsForTableNotDelivered&tableid=19&_=1601211883119 HTTP/1.1" 200 33 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:07 +0200] "GET /img/gray.png?t=1601212077688 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
127.0.0.1 - - [27/Sep/2020:15:08:07 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511229 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:08:08 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:08 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
192.168.178.20 - - [27/Sep/2020:15:08:08 +0200] "GET /php/contenthandler.php?module=admin&command=isPrinterServerActive&_=1601211883120 HTTP/1.1" 200 75 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:09 +0200] "GET /img/gray.png?t=1601212079689 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
127.0.0.1 - - [27/Sep/2020:15:08:10 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511275 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:11 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:08:11 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:11 +0200] "GET /img/gray.png?t=1601212081880 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:13 +0200] "GET /php/contenthandler.php?module=admin&command=getDailycode&_=1601211883121 HTTP/1.1" 200 53 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:13 +0200] "GET /img/gray.png?t=1601212083882 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:13 +0200] "GET /php/contenthandler.php?module=admin&command=isPrinterServerActive&_=1601211883122 HTTP/1.1" 200 75 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
127.0.0.1 - - [27/Sep/2020:15:08:14 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511321 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:14 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:08:14 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:14 +0200] "GET /php/contenthandler.php?module=queue&command=getJsonLongNamesOfProdsForTableNotDelivered&tableid=19&_=1601211883123 HTTP/1.1" 200 33 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:15 +0200] "GET /img/gray.png?t=1601212085880 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:17 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:08:17 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511367 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:17 +0200] "GET /img/gray.png?t=1601212087881 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
127.0.0.1 - - [27/Sep/2020:15:08:17 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:18 +0200] "GET /php/contenthandler.php?module=admin&command=isPrinterServerActive&_=1601211883124 HTTP/1.1" 200 75 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:19 +0200] "GET /img/gray.png?t=1601212089880 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:20 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:08:20 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511413 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:08:20 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:21 +0200] "GET /img/gray.png?t=1601212091881 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:23 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
192.168.178.20 - - [27/Sep/2020:15:08:23 +0200] "GET /php/contenthandler.php?module=admin&command=getDailycode&_=1601211883125 HTTP/1.1" 200 53 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:23 +0200] "GET /img/gray.png?t=1601212093885 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:23 +0200] "GET /php/contenthandler.php?module=admin&command=isPrinterServerActive&_=1601211883126 HTTP/1.1" 200 75 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
127.0.0.1 - - [27/Sep/2020:15:08:23 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511459 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:08:24 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:25 +0200] "GET /php/contenthandler.php?module=queue&command=getJsonLongNamesOfProdsForTableNotDelivered&tableid=19&_=1601211883127 HTTP/1.1" 200 33 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:25 +0200] "GET /img/gray.png?t=1601212095878 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:26 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:08:27 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511505 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:27 +0200] "GET /img/gray.png?t=1601212097881 HTTP/1.1" 200 160 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
127.0.0.1 - - [27/Sep/2020:15:08:27 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:28 +0200] "POST /php/contenthandler.php?module=queue&command=addProductListToQueue HTTP/1.1" 500 5 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:28 +0200] "GET /php/contenthandler.php?module=admin&command=isPrinterServerActive&_=1601211883128 HTTP/1.1" 200 75 "https://krusty/waiter.html?v=2.0.5" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36"
192.168.178.20 - - [27/Sep/2020:15:08:29 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:08:31 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511551 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:08:31 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:32 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:08:34 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511597 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:08:34 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:35 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:08:37 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511643 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:08:38 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:38 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:08:41 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511689 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:08:41 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456335 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:41 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:08:44 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511735 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:08:44 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:45 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:08:47 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511781 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:08:47 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:48 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:08:50 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511827 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:08:51 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456342 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:51 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:08:54 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511873 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:08:54 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:54 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:08:57 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511919 "-" "Wget/1.20.3 (linux-gnu)"
127.0.0.1 - - [27/Sep/2020:15:08:57 +0200] "POST //php/contenthandler.php?module=bill&command=autoBackupPdfSummary&lang=0 HTTP/1.1" 200 456341 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:08:58 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"
127.0.0.1 - - [27/Sep/2020:15:09:00 +0200] "POST //php/contenthandler.php?module=admin&command=autobackup HTTP/1.1" 200 1511965 "-" "Wget/1.20.3 (linux-gnu)"
192.168.178.20 - - [27/Sep/2020:15:09:01 +0200] "POST /php/contenthandler.php?module=printqueue&command=getNextTicketJobs&fl=16&printersizes=R_30_30_30_30_30_30-F_30_30_30_30-D_30_30_30_30-P_30&v=2.0.5.0&pid=3008&thr=4&instance=1 HTTP/1.1" 200 37 "-" "-"

Wie man sieht, habe ich aus Versehen das Backup alle 2 Sekunden ausgeführt. Das ist mittlerweile gefixt. Könnte das eine Ursache sein? Aber sollte das nicht trotzdem nicht zu so einem Fehler führen?

Wäre es eventuell möglich den Arbeitsbon erneut ausdrucken zu können?

Grüße
André
Zuletzt geändert von misery am So 27. Sep 2020, 19:00, insgesamt 1-mal geändert.
pichel
Administrator
Beiträge: 1154
Registriert: So 13. Sep 2015, 19:48
Wohnort: Hamburg
Kontaktdaten:

Re: Deadlock found when trying to get lock

Beitrag von pichel »

Hallo André,

ich nehme an, dass die Bestellung gar nicht erst richtig in der DB eingespeichert würde, weil die Signierung fehlgeschlagen ist. Daher wirst du also keinen Arbeitsbon darüber drucken können.

Diesen Fehler habe ich nicht richtig abgefangen.

Ich kann auch nicht sagen, ob ein zu häufiges Abfragen der Druckjops dazu geführt hat. eigentlich sollte das nicht der Fall sein. Ich untersuche das noch.

Gruß,

Stefan
Stefan Pichel
Entwickler der Kassensoftware OrderSprinter (http://www.ordersprinter.de)
misery
Beiträge: 36
Registriert: Do 24. Sep 2020, 09:53

Re: Deadlock found when trying to get lock

Beitrag von misery »

Inwiefern hat die Signatur nicht funktioniert?
Hier das TSE-Log zu der Uhrzeit.

Code: Alles auswählen

Sep 27 14:55:28 krusty tse.sh[162033]:   TSESerialNo: [B@1f758b24
Sep 27 14:55:28 krusty tse.sh[162033]:   TSEPublicKey: BCn386oaCnCLHi8eElxESIXWYME8avJZZnTxCx7acSV/3JiyI1QnwOigwt4beqICTw678eqQBGP/SpJA54z32nyJQ8eCeygkSpSO6ksJSfbBsF6K091KlTFNzSzlTj4pZg==
Sep 27 14:55:28 krusty tse.sh[162033]: {"sigcounter":48,"signature":"Q7B8yfvPb0kUS91KP4wbhfE8lUFY5TfZS3Lq3istBKMVCIY\/hYC7PyJ9tY1i5oEWdj+HmG3V\/I9hR10F6wV3wQeAlYrMlBssu\/tc0kykNPEJtri5AACxx\/8uvYcCcQY0","publickey":"BCn386oaCnCLHi8eElx>
Sep 27 15:08:27 krusty tse.sh[162033]: Transferred POST-Data: {"pass":"XXX","pin":[],"clientid":"ORD1","cmd":"signorders","value":"1;\"Joghurt Amarena\";5.60\n1;\"Erdbeer Becher\";5.60\n1;\"Milchkaffee\";2.40\n1;\"Waffeln Ki>
Sep 27 15:08:27 krusty tse.sh[162033]: Request Handler. Post Data: {"pass":"XXX","pin":[],"clientid":"ORD1","cmd":"signorders","value":"1;\"Joghurt Amarena\";5.60\n1;\"Erdbeer Becher\";5.60\n1;\"Milchkaffee\";2.40\n1;\"Waffe>
Sep 27 15:08:27 krusty tse.sh[162033]: Parse into class this string: {"pass":"XXX","pin":[],"clientid":"ORD1","cmd":"signorders","value":"1;\"Joghurt Amarena\";5.60\n1;\"Erdbeer Becher\";5.60\n1;\"Milchkaffee\";2.40\n1;\"Waf>
Sep 27 15:08:27 krusty tse.sh[162033]: Start Update Time with unixTime 1601212107
Sep 27 15:08:27 krusty tse.sh[162033]: Logged in
Sep 27 15:08:27 krusty tse.sh[162033]: Completed Update Time at TSE
Sep 27 15:08:27 krusty tse.sh[162033]: Starte Signierung
Sep 27 15:08:28 krusty tse.sh[162033]:   Last Transaction Details
Sep 27 15:08:28 krusty tse.sh[162033]:   Log Time: 1601212107
Sep 27 15:08:28 krusty tse.sh[162033]:   Signature Counter: 52
Sep 27 15:08:28 krusty tse.sh[162033]:   Transaction Number: 16
Sep 27 15:08:28 krusty tse.sh[162033]:   Log Message Length: 313
Sep 27 15:08:28 krusty tse.sh[162033]:   Process Data Length: 95
Sep 27 15:08:28 krusty tse.sh[162033]:   Log Message:
Sep 27 15:08:28 krusty tse.sh[162033]: 30820135020102060904007F000703070101801146696E6973685472616E73616374696F6E81044F524431825F313B224A6F676875727420416D6172656E61223B352E36300A313B224572646265657220426563686572223B352E36300A313B224D>
Sep 27 15:08:28 krusty tse.sh[162033]:   SigAlg: ecdsa-plain-SHA384
Sep 27 15:08:28 krusty tse.sh[162033]:   Signature: KHydbt6D2dOAwxMJsqyWy+l3hiJASShmirV3Af6E8h60o78QfTt8Z4rR4gGB/KrAL7cbxjiuI56En21GJtKv7hJx6hN7ugGHn+742eRn6jvnkMmyxD9yYYOZFfN2QtKw
Sep 27 15:08:28 krusty tse.sh[162033]:   TSESerialNo: [B@47409986
Sep 27 15:08:28 krusty tse.sh[162033]:   TSEPublicKey: BCn386oaCnCLHi8eElxESIXWYME8avJZZnTxCx7acSV/3JiyI1QnwOigwt4beqICTw678eqQBGP/SpJA54z32nyJQ8eCeygkSpSO6ksJSfbBsF6K091KlTFNzSzlTj4pZg==
Sep 27 15:08:28 krusty tse.sh[162033]: {"sigcounter":52,"signature":"KHydbt6D2dOAwxMJsqyWy+l3hiJASShmirV3Af6E8h60o78QfTt8Z4rR4gGB\/KrAL7cbxjiuI56En21GJtKv7hJx6hN7ugGHn+742eRn6jvnkMmyxD9yYYOZFfN2QtKw","publickey":"BCn386oaCnCLHi8eElxESI>
Sep 27 15:18:41 krusty tse.sh[162033]: Transferred POST-Data: {"pass":"XXX","pin":[],"clientid":"ORD1","cmd":"signorders","value":"1;\"Gutschein einloesen\";-12.00"}
Sep 27 15:18:41 krusty tse.sh[162033]: Request Handler. Post Data: {"pass":"XXX","pin":[],"clientid":"ORD1","cmd":"signorders","value":"1;\"Gutschein einloesen\";-12.00"}
Sep 27 15:18:41 krusty tse.sh[162033]: Parse into class this string: {"pass":"XXX","pin":[],"clientid":"ORD1","cmd":"signorders","value":"1;\"Gutschein einloesen\";-12.00"}
Sep 27 15:18:41 krusty tse.sh[162033]: Starte Signierung
pichel
Administrator
Beiträge: 1154
Registriert: So 13. Sep 2015, 19:48
Wohnort: Hamburg
Kontaktdaten:

Re: Deadlock found when trying to get lock

Beitrag von pichel »

Das ist dann ja noch schlimmer. dann hat also die Signierung funktioniert, aber die Speicherung des Vorgangs in der Datenbank ist fehlgeschlagen. Und zusätzlich hat der Benutzer keine Information darüber bekommen.

Aber ich schaue mir das gerade hier an einem kleinen Smartphone an, da fehlt die Übersicht und verspreche aber, dass ich mir morgen die Situation genauer am richtigen Entwicklungsrechner anschauen.

Gruß,

Stefan
Stefan Pichel
Entwickler der Kassensoftware OrderSprinter (http://www.ordersprinter.de)
misery
Beiträge: 36
Registriert: Do 24. Sep 2020, 09:53

Re: Deadlock found when trying to get lock

Beitrag von misery »

Ich habe das jetzt auf meinem Demo-System ausprobiert und meine Vermutung bestätigt.

Ich habe den TSE-Simulator verwendet und auf der Konsole folgendes Skript ausgeführt um einen Teil des Backups zu testen und auf jeden Fall die Race-Condition zu provozieren.

Code: Alles auswählen

#!/bin/bash
while :
do
        mysqldump ordersprinter_db > dummy
        echo "Press [CTRL+C] to stop.."
done

Während das Skript ordentlich Backup-Load erzeugt, macht man eine Bestellung und es knallt auch auf meinem Demo-System wie folgt.

Code: Alles auswählen

2020/09/27 20:51:22 [error] 4063#4063: *2026 FastCGI sent in stderr: "PHP message: PHP Fatal error:  Uncaught PDOException: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction 
in /webapp/php/commonutils.php:334
Stack trace:
#0 /webapp/php/commonutils.php(334): PDOStatement->execute(Array)
#1 /webapp/php/utilities/operations.php(42): CommonUtils::execSql(Object(PDO), 'INSERT INTO %op...', Array)
#2 /webapp/php/queuecontent.php(1447): Operations::createOperation(Object(PDO), 2, 2, 1601232681, 2, '1;"Gutschein";7...', 'fbaGExar80UOZ3X...', '13', '9', '14', '15', 2, 1)
#3 /webapp/php/queuecontent.php(1368): QueueContent::signAtTSE(Object(PDO), '1;"Gutschein";7...', Array, false)
#4 /webapp/php/queuecontent.php(1125): QueueContent->addProductListToQueueCore(Object(PDO), '2020-09-27 20:5...', '2', Array, '1', 's', '2', 0)
#5 /webapp/php/queuecontent.php(76): QueueContent->addProductListToQueue('2', Array, '1', 's')
#6 /webapp/php/contenthandler.php(65): QueueContent->handleCommand('addProductListT...')
#7 {main}" while reading response header from upstream, client: 192.168.111.77, server: , request: "POST /php/contenthandler.php?module=queue&command=addProductListToQueue HTTP/1.1", upstream: "fastcgi://unix:/run/php.sock:", host: "192
.168.111.62", referrer: "http://192.168.111.62/waiter.html"
Es beruhigt mich jetzt erst mal, dass es am gleichzeitigen Backup liegt und ich das schon korrigiert habe.
Die Vermutung liegt bei mir allerdings nah, dass das Problem auch bei sehr großer Last von vielen Kellner gleichzeitig auftreten kann?

André
misery
Beiträge: 36
Registriert: Do 24. Sep 2020, 09:53

Re: Deadlock found when trying to get lock

Beitrag von misery »

Moin Stefan,

danke für die 2.0.6! Ich habe sie auf mein Test-System installiert und versucht das Problem erneut zu provozieren.
Gut ist, dass es zu keinem seltsamen Fehler mehr kommt. Jedoch kommt man nach drücken von "Arbeitsbon" auf die Tisch-Auswahl und es gibt keine Bestellung für den Tisch. Wenn ich direkt "Kasse" drücke, komme ich korrekt zum Rechnungsdruck - aber ohne irgendwelche Artikel.

Das TSE bekommt trotzdem noch die Daten - die Bestellung kommt aber nicht an.

Code: Alles auswählen

isCheckUseful = false: current = 1601727766, lastSucces=1601727666
Transferred POST-Data: {"pass":"XXX","pin":[YYY],"clientid":"ORD1","cmd":"check"}
isCheckUseful = false: current = 1601727771, lastSucces=1601727666
Transferred POST-Data: {"pass":"XXX","pin":[YYY],"clientid":"ORD1","cmd":"signorders","value":"1;\"Weizenbier\";3.00"}
Starte Simulation der Signierung
  Last Transaction Details
  Log Time: 1601727772
  Signature Counter: 5
  Transaction Number: 5
  Log Message Length: 3081DC020102060904007F000703070101801146696E6973685472616E73616374696F6E810...
  SigAlg: ecdsa-plain-SHA384
  Signature: QWWAzhyH5ymMzKa/O1dFrRttnNrPSXaXWNJRFr/YER5UBhhcpduwneiuhguM1tpRWTUsh+qysXsqUl39Zh14VeITQib2tWxpUrX778V7CrZ4q2yY+8ExppfflHCRoiYc
  TSESerialNo: [B@6fea8c51
  TSEPublicKey: BFa72LLBEGO5ycFraOubP491AuEnnaikkJqt9CcCIMVyyxdbR+O7f1QYBsoX4zuuzyOCPhKvohCwm6OrJujdimZQVLqUsYj6KSh/S07bqxZ6d/5npEKEmx9pNRy0b1qQOg==
[/code}
pichel
Administrator
Beiträge: 1154
Registriert: So 13. Sep 2015, 19:48
Wohnort: Hamburg
Kontaktdaten:

Re: Deadlock found when trying to get lock

Beitrag von pichel »

Moin,

der Behandlung des Events zur Übernittlung an der Bestellung an den Server ist (noch) asynchron, d.h. bei einem Fehler erfährt der Benutzer es gegenbenfalls erst nach einer bestimmten Wartezeit (bei "Bestellung senden" und "Arbeitsbon") oder gar nicht ("Kasse"). Das sollte ich also auch noch ändern.

Aber trotzdem liegt bei dir offenbar ein Fehler vor, den ich so bei mir nicht reproduzieren kann. Magst du mal in der config.php E_ERROR durch E_ALL ersetzen und per "Arbeitsbon" eine Bestellung an den Server schicken (mit aktivierter TSE) und etwas warten? Erscheint nach max. 1 Minute eine Fehlermeldung? Kannst du unabhängig davon auch mal das Error-Log senden, welches den Fehlerzeitpunkt abdeckt?

Gruß,

Stefan
Stefan Pichel
Entwickler der Kassensoftware OrderSprinter (http://www.ordersprinter.de)
misery
Beiträge: 36
Registriert: Do 24. Sep 2020, 09:53

Re: Deadlock found when trying to get lock

Beitrag von misery »

Moin Stefan,

habe ich gleich mal probiert. Bei mir erscheint auch nach ca. einer Minute keine Fehlermeldung.

Im Error log ist folgendes

Code: Alles auswählen

2020/10/03 16:13:03 [error] 2491#2491: *11 FastCGI sent in stderr: "PHP message: PHP Notice:  Trying to get property 'kind' of non-object in /2.0.6/php/queuecontent.php on line 540PHP message: PHP Notice:  Trying to get property 'kind' of non-object in /2.0.6/php/queuecontent.php on line 540" while reading response header from upstream, client: 192.168.111.77, server: , request: "POST /php/contenthandler.php?module=queue&command=addProductListToQueue HTTP/1.1", upstream: "fastcgi://unix:/run/php.sock:", host: "192.168.111.62", referrer: "https://192.168.111.62/waiter.html"

Code: Alles auswählen

[03-Oct-2020 16:11:46] NOTICE: fpm is running, pid 2366
[03-Oct-2020 16:11:46] NOTICE: ready to handle connections
[03-Oct-2020 16:13:03] WARNING: [pool www] child 2390 said into stderr: "NOTICE: PHP message: PHP Notice:  Trying to get property 'kind' of non-object in /2.0.6/php/queuecontent.php on line 540"
[03-Oct-2020 16:13:03] WARNING: [pool www] child 2390 said into stderr: "NOTICE: PHP message: PHP Notice:  Trying to get property 'kind' of non-object in /2.0.6/php/queuecontent.php on line 540"
Was macht eigentlich das Finanzamt wenn des Lücken der Signatur-ID gibt? Wenn das TSE signiert aber das nirgends gespeichert wird, fehlt ja eine ID. Ich habe die Befürchtung, dass das Finanzamt dann Manipulation vorwirft.

Viele Grüße
André
pichel
Administrator
Beiträge: 1154
Registriert: So 13. Sep 2015, 19:48
Wohnort: Hamburg
Kontaktdaten:

Re: Deadlock found when trying to get lock

Beitrag von pichel »

Hallo André,

die Meldung "Trying to get property 'kind' of non-object" entsteht dann, wenn der Typ von Arbeitsaufträgen abgefragt werden soll, die es nicht mehr gibt, z.B. weil die Transaktion zwar neue WorkJobs angelegt hat, diese aber durch ein Rollback nicht mehr zur Verfügung stehen. In dem Fall hätte ich aber eine Exception davor erwartet, die ich in deinem error-log-Ausschnitt nicht sehen kann. Kurze Frage: Du nutzt auch die InnoDB als DB-Engine?

Sind noch Arbeitsaufträge drin, die mit einer 2.0.5 oder früher erstellt wurden? In dem Fall lösche die bitte aus der Druckerwarteschlange (in der Administrationsansicht) und versuche dein Glück erneut. Vielleicht mit einer 2.0.7:

Ich habe in der 2.0.7 nun die Möglichkeit eingebaut, den Loglevel festzulegen und damit die Menge der Ausgaben zu begrenzen (in der Voreinstellung werden nun nur noch die wichtigsten Ausgabe inkl. Signierungsaktivitäten mitgeloggt). Es kann sein, dass das umfangreiche Logging in 2.0.6 zu Problemen mit dem verfügbaren Puffer in Windows-CMD-Shells führen konnte.

Deine letzte Frage ist wohl mehr rhetorischer Art. Ich arbeite daran, dass das eigentlich nicht passiert. Wenn es aber in der Anfangszeit passiert, wo die Software offenbar noch Bugs enthält, ist ein Hinweis auf diese Forenbeiträge im Falle einer Steuerprüfung vielleicht hilfreich.

Gruß,

Stefan
Stefan Pichel
Entwickler der Kassensoftware OrderSprinter (http://www.ordersprinter.de)
misery
Beiträge: 36
Registriert: Do 24. Sep 2020, 09:53

Re: Deadlock found when trying to get lock

Beitrag von misery »

Moin Stefan,

danke für die Hilfe.
Nee, ich meinte die Frage schon ernst. Könnte ja sein, dass es da irgendein Feld gibt, wie "TSE-Fehler" oder so, was dann in Ordnung wäre. :-)

Mh, leider klappt es mit der 2.0.7 auch noch nicht. Ich hatte eben ein "too slow" error log. Aber da ich mir unsicher war, ob das alles so richtig durchgestartet hatte, habe ich von vorne angefangen. Jetzt kommt das nicht mehr, sondern nur noch das, was es vorher schon war. Es kommt auch nicht nachträglich ein Fehler.

Code: Alles auswählen

[04-Oct-2020 10:19:27] WARNING: [pool www] child 2891 said into stderr: "NOTICE: PHP message: PHP Notice:  Trying to get property 'kind' of non-object in /2.0.7/php/queuecontent.php on line 540"
[04-Oct-2020 10:19:27] WARNING: [pool www] child 2891 said into stderr: "NOTICE: PHP message: PHP Notice:  Trying to get property 'kind' of non-object in /2.0.7/php/queuecontent.php on line 540"
Ja, da ist die InnoDB im Einsatz. Da läuft eine MariaDB 10.4.13.
Ich kann dir das auch als .ova zur Verfügung stellen. Ich habe mein Testsystem in einer VM.

Viele Grüße
André
Antworten