BUG: TSE Connector

In diesem Forum können Fragen zum OrderSprinter gestellt werden.
Antworten
pichel
Administrator
Beiträge: 1170
Registriert: So 13. Sep 2015, 19:48
Wohnort: Hamburg
Kontaktdaten:
Kontaktdaten von pichel

Re: BUG: TSE Connector

Beitrag von pichel »

Hallo,

vielen Dank für die vielen Beiträge. Leider ist freie Zeit aktuell ein ganz rares Gut bei mir. Aber da in diesem Forum viele Entwickler sind, stelle ich gerne den Source-Code des TSEConnectors online. Vielleicht sieht ja jemand den Fehler. Ich habe auch nichts dagegen, wenn jemand anderes sich an einem Bugfix versucht und eine reparierte Version allen zur Verfügung stellt... :)

Vielleicht ein kleines Schaubild, wie der TSEConnector funktioniert:
model.png
model.png (58.25 KiB) 1986 mal betrachtet
Die Sources habe ich angehängt. Der Quelltext entspricht zwar nicht ganz der Version 2.0.7, weil ich mittlerweile weitergearbeitet habe, aber funktional ist es schon der gleiche Code.

Ansonsten werde ich selbst versuchen, wenigstens am Wochenende ein wenig Zeit in den TSEConnector zu stecken.

Noch ein kleiner Hinweis, weil er in diesem Kontext relevant ist: Der Webserver des TSEConnectors behandelt alle eingehenden Requests nacheinander und die TSE würde auch keine asynchronen Anfragen vertragen. Nun ergibt sich jedoch das Problem, dass die TSE regelmäßig (mindestens einmal in 25 Stunden) einen Selbsttest benötigt und die Uhrzeit gestellt werden muss (und nach dem Stellen der Uhrzeit kann erneut ein Selbsttest notwendig werden). Hätte ich diesen Check im TSEConnector durch einen IntervalTimer jede Stunde durchgeführt, hätte ich mich wieder darum kümmern müssen, das auch zu synchronisieren. Stattdessen habe ich die Methode isPrinterActive, die bei einem eingeloggten Benutzer alle 10 Minuten in der Kernapplikation aufgerufen wird, um einen REST-Aufruf zum Checken der TSE erweitert, so dass dies wieder als synchroner Aufruf behandelt wird. Im TSEConnector selbst möchte ich die TSE aber nicht alle 10 Sekunden abfragen, sondern habe durch die Klasse TseStatus festgelegt, dass diese Anfragen nur alle 30 Minuten tatsächlich bis zur TSE durchgereicht werden. Ja, das ist unschön und ein hässlicher Workaround und sollte auch nicht die finale Lösung sein...

Gruß,

Stefan

Update 12.10.2020: Sources wieder entfernt, denn der Code war ohnehin fehlerhaft
Stefan Pichel
Entwickler der Kassensoftware OrderSprinter (http://www.ordersprinter.de)
Nach oben
staebners
Beiträge: 17
Registriert: Fr 25. Sep 2020, 13:31

Re: BUG: TSE Connector

Beitrag von staebners »

Vielen Dank, Herr Pichel!

Ich fürchte mit meinem gefährlichen Halbwissen im Java-Umfeld bin ich da keine Hilfe bei der Programmierung.
Stelle mich aber gerne als Versuchskarnickel zur Verfügung.
Bin insbesondere am Sonntag unter der bekannten Nummer erreichbar- und der Laden ist zu :D .

Melden Sie Sich doch heute oder Samstag, wenn das hilft.

Gruß, GG
Nach oben
misery
Beiträge: 36
Registriert: Do 24. Sep 2020, 09:53

Re: BUG: TSE Connector

Beitrag von misery »

Moin Stefan,

ich denke, ich habe das Problem gefunden.

Laut maxTimeSynchronizationDelay braucht das TSE alle 30 Minuten die Uhrzeit. Das hast du ja auch so im Check abgespeichert und sogar noch ein bisschen Puffer berücksichtig. Dein periodischer Check mit "isCheckUseful" versucht dies auch rechtzeitig zu machen.
Das sieht man auch im Log:

Code: Alles auswählen

Oct 07 10:38:42 Check for TSE Status and availability
Oct 07 11:08:45 Check for TSE Status and availability
Oct 07 13:13:13 Check for TSE Status and availability
Oct 07 13:43:18 Check for TSE Status and availability
Oct 07 14:13:23 Check for TSE Status and availability
Oct 07 14:43:28 Check for TSE Status and availability
Die Uhrzeit wird dann eventuell neu gesetzt.

Code: Alles auswählen

Oct 07 10:38:42 TSE has no valid time. Set time now.
Oct 07 11:08:59 TSE has no valid time. Set time now.
Oct 07 13:13:13 TSE has no valid time. Set time now.
Oct 07 14:13:23 TSE has no valid time. Set time now.
Wenn der Check dann durchläuft, fragst du das TSE, ob es eine gültige Zeit hat. Wenn dem so ist, setzt du die Zeit nicht. Vermutlich hat das TSE gerade noch für paar Sekunden/Minuten eine gültige Zeit. Aber dein nächster Check, läuft erst wieder in ca. 30 Minuten. Also zu spät.

Code: Alles auswählen

boolean hasValidTime = wormStore.info().hasValidTime();
if (!hasValidTime) {
    // set the time
    logger.log2("TSE has no valid time. Set time now.");
    wormStore.tse_updateTime(timestamp);
}
Ich würde daher in dem periodischen Checker die "hasValidTime()"-Abfrage rausnehmen.

Ich würde aber auch vor jeder Signatur zur Vorsicht immer wormStore.info().hasValidTime(); prüfen und ggf. dann setzen. Dann kann nix schief gehen.

Viele Grüße
André
Nach oben
misery
Beiträge: 36
Registriert: Do 24. Sep 2020, 09:53

Re: BUG: TSE Connector

Beitrag von misery »

Moin,

ich habe mal meinen Vorschlag umgesetzt.

Code: Alles auswählen

diff --git a/src/main/java/tseconnector/commands/TseAdminCommand.java b/src/main/java/tseconnector/commands/TseAdminCommand.java
--- a/src/main/java/tseconnector/commands/TseAdminCommand.java
+++ b/src/main/java/tseconnector/commands/TseAdminCommand.java
@@ -293,12 +293,12 @@ public class TseAdminCommand extends Bas
                }
            }
            // now check for the time.
-           boolean hasValidTime = wormStore.info().hasValidTime();
-           if (!hasValidTime) {
+//         boolean hasValidTime = wormStore.info().hasValidTime();
+//         if (!hasValidTime) {
                // set the time
-               logger.log2("TSE has no valid time. Set time now.");
+               logger.log2("TSE: Set time now.");
                wormStore.tse_updateTime(timestamp);
-           }
+//         }
            tseStatus.setTseTimeSet(true);
            // the time setting may have invalidated the self test, so check again
            hasValidSelfTest = wormStore.info().hasPassedSelfTest();
Wichtig: Ich habe das nicht mit einem echten TSE getestet.
https://www.dropbox.com/s/v6ktquyd2ydvl ... r.jar?dl=0

Vielleicht hilft es ja jemandem. Feedback dazu wäre gut. :-)
Ich übernehme natürlich keine Haftung. ;-) Ich habe aber bis auf die Änderung oben und das Hinzufügen vom Maven-Build-System nichts geändert.

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

Re: BUG: TSE Connector

Beitrag von pichel »

Hallo André,

vielen vielen Dank für deine wertvollen Beiträge in diesem Forum und auch der Bereitstellung einer verbesserten TSEConnector-Version.

Ich glaube, ein Hauptfehler war es, dass ich im TseStatus die Methode setTseTimeSet(true) unabhängig davon aufgerufen habe, ob wirklich ein Sync der Zeit stattgefunden hat und somit wurde der Check isTimeSet im TseStatus nie false.

Aber es gab noch andere Probleme, die ich nun hoffentlich mit der 2.0.8 repariert habe:
- zwischen einem Check auf hasValidTime des wormStores kann es ja ein paar Millisekunden dauern, bis die Signierung erfolgt, denn ich schließe den Stream (es wird ein Flush durchgeführt) und öffne ihn erneut. Die Wahrscheinlichkeit, dass dazwischen die Zeit ungültig wird, ist sehr klein, aber es soll ja auch immer zuverlässig funktionieren
- wenn die TSE in den Low Energy Mode übergeht (was sie macht, wenn kein regelmäßiger Time Sync stattfindet, z.B. bei ausgeloggten Benutzern in der Kernapplikation), kann das erste Kommando danach schiefgehen (d.h. ein Time Sync wird in eine Exception münden). Hier hilft dann nur noch ein Self Test.

Ich habe versucht, diese beiden Fälle auch abzufangen und habe eine 2.0.8 gebaut. Allerdings geht es mir gerade ähnlich wie dir: die Entwickller-TSE ist an einem anderem Ort als ich und so kann ich nicht testen. Obwohl ich meine, sehr sorgfältig gearbeitet zu haben, bin ich auf meine Anwender zum Testen angewiesen.

Deswegen Aufruf an alle Anwender: Bitte testet es und wenn es Probleme gibt, sendet mir bitte die Ausgabe von http://localhost:8000/info?getlog zu.

Ach ja, es reicht, wenn man aus dem 2.0.8-Download nur den TSEConnector nimmt, denn die Schnittstelle zwischen Kernapplikation und TSEConnector hat sich nicht geändert.

Gruß,

Stefan
Stefan Pichel
Entwickler der Kassensoftware OrderSprinter (http://www.ordersprinter.de)
Nach oben
os_user

Re: BUG: TSE Connector

Beitrag von os_user »

Hallo Zusammen,
habe gestern Abend das Update noch installiert. Alles scheint stabil zu laufen auch ohne automatischen Neustart. Super!
Nach oben
misery
Beiträge: 36
Registriert: Do 24. Sep 2020, 09:53

Re: BUG: TSE Connector

Beitrag von misery »

Moin,

mal als Rückmeldung... ich hatte die 2.0.8 gleich am Montag aufgespielt. Seit dem ist kein weiterer TSE-Fehler mehr aufgetreten.
Dann sollte sich der Bug wohl erledigt haben. :-)

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

Re: BUG: TSE Connector

Beitrag von misery »

Bisher ist es nun einmal seit dem Update auf die 2.0.8 zu einem TSE-Problem gekommen.

Hier das vollständige TSE-Log von dem Tag.

Code: Alles auswählen

08:00:00 systemd[1]: Stopping TSE...
08:00:00 systemd[1]: tse.service: Succeeded.
08:00:00 systemd[1]: Stopped TSE.
08:00:00 systemd[1]: Started TSE.
08:00:01 : TSEConnectors kann folgende Parameter verarbeiten:
08:00:01 :    pass=xyz     Das Passwort des TSEConnectors. In der OrderSprinter-Administrationsansicht einstellen!
08:00:01 :    port=8000    Der TCP-Port, über den OrderSprinter-Core mit dem TSEConnector kommunizieren soll
08:00:01 :    mountpoint=/media/account/SWISSBIT   Das Laufwerk/Mountpoint der Swissbit-TSE
08:00:01 :    mode=normal  Falls der Wert auf "simulate" eingestellt wird, wird die TSE nur simuliert.
08:00:01 :    loglevel=number  0: nur relevante Infos, 1: Signierungen, 2: umfangreiches Logging.
08:00:01 :    showlog=number  0: kein Zugriff auf Log via Web, 1: Zugriff erlauben ohne Passwortabfrage (default: 1)
08:00:01 : Zusätzlich muss der Pfad zum Verzeichnis tseconnector_lib angegeben werden (sonst wird ein java.lang.UnsatisfiedLinkError gemeldet):
08:00:01 :    z.B. java -Djava.library.path=/usr/local/bin/tseconnector/swissbit/nativelibs/linux64 -jar tseconnector.jar mode=...
08:00:01 : 08:00:01.534: Start TSEConnector mit diesen Parametern:
08:00:01 : 08:00:01.570:   pass=      XXX
08:00:01 : 08:00:01.570:   port=      6666
08:00:01 : 08:00:01.570:   supplier=  swissbit
08:00:01 : 08:00:01.571:   mountpoint=/mnt/tse
08:00:01 : 08:00:01.571:   mode=      normal
08:00:01 : 08:00:01.571:   loglevel=  2
08:00:01 : 08:00:01.571:   showlog=   1
08:00:01 : TSE seems to be mounted
08:00:01 : Sync Time = 1800 seconds (30 minutes)
08:00:01 : 08:00:01.642: Abgeschlossen Startup des TSEConnectors
13:55:54 : 13:55:54.905: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:55:55 : 13:55:55.775: isCheckUseful = true: current = 1603194955, lastSucces=0
13:55:55 : 13:55:55.776: Check for TSE Status and availability
13:55:55 : 13:55:55.785: TSE has no valid time. Set time now.
13:55:55 : 13:55:55.786: TSE needs time sync because soon expiration of maxSyncTime after last time sync
13:55:56 : 13:55:56.147: TSE time is set
13:55:56 : 13:55:56.552: TSE time is set
13:55:59 : 13:55:59.901: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:55:59 : 13:55:59.914: isCheckUseful = false: current = 1603194959, lastSucces=1603194956
13:55:59 : 13:55:59.914: Ignore Check request - last check not that far in the past
13:56:04 : 13:56:04.907: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:56:04 : 13:56:04.914: isCheckUseful = false: current = 1603194964, lastSucces=1603194956
13:56:04 : 13:56:04.914: Ignore Check request - last check not that far in the past
13:56:09 : 13:56:09.900: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:56:09 : 13:56:09.911: isCheckUseful = false: current = 1603194969, lastSucces=1603194956
13:56:09 : 13:56:09.912: Ignore Check request - last check not that far in the past
13:56:14 : 13:56:14.905: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:56:14 : 13:56:14.917: isCheckUseful = false: current = 1603194974, lastSucces=1603194956
13:56:14 : 13:56:14.918: Ignore Check request - last check not that far in the past
13:56:19 : 13:56:19.900: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:56:19 : 13:56:19.911: isCheckUseful = false: current = 1603194979, lastSucces=1603194956
13:56:19 : 13:56:19.911: Ignore Check request - last check not that far in the past
13:56:24 : 13:56:24.906: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:56:24 : 13:56:24.917: isCheckUseful = false: current = 1603194984, lastSucces=1603194956
13:56:24 : 13:56:24.917: Ignore Check request - last check not that far in the past
13:56:29 : 13:56:29.902: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:56:29 : 13:56:29.909: isCheckUseful = false: current = 1603194989, lastSucces=1603194956
13:56:29 : 13:56:29.910: Ignore Check request - last check not that far in the past
13:56:34 : 13:56:34.906: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:56:34 : 13:56:34.916: isCheckUseful = false: current = 1603194994, lastSucces=1603194956
13:56:34 : 13:56:34.916: Ignore Check request - last check not that far in the past
13:56:39 : 13:56:39.902: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:56:39 : 13:56:39.909: isCheckUseful = false: current = 1603194999, lastSucces=1603194956
13:56:39 : 13:56:39.909: Ignore Check request - last check not that far in the past
13:56:44 : 13:56:44.906: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:56:44 : 13:56:44.921: isCheckUseful = false: current = 1603195004, lastSucces=1603194956
13:56:44 : 13:56:44.921: Ignore Check request - last check not that far in the past
13:56:49 : 13:56:49.948: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:56:49 : 13:56:49.963: isCheckUseful = false: current = 1603195009, lastSucces=1603194956
13:56:49 : 13:56:49.964: Ignore Check request - last check not that far in the past
13:56:54 : 13:56:54.907: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:56:54 : 13:56:54.918: isCheckUseful = false: current = 1603195014, lastSucces=1603194956
13:56:54 : 13:56:54.919: Ignore Check request - last check not that far in the past
13:56:59 : 13:56:59.903: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:56:59 : 13:56:59.911: isCheckUseful = false: current = 1603195019, lastSucces=1603194956
13:56:59 : 13:56:59.912: Ignore Check request - last check not that far in the past
13:57:04 : 13:57:04.908: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:57:04 : 13:57:04.920: isCheckUseful = false: current = 1603195024, lastSucces=1603194956
13:57:04 : 13:57:04.921: Ignore Check request - last check not that far in the past
13:57:09 : 13:57:09.904: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:57:09 : 13:57:09.920: isCheckUseful = false: current = 1603195029, lastSucces=1603194956
13:57:09 : 13:57:09.921: Ignore Check request - last check not that far in the past
13:57:14 : 13:57:14.908: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:57:14 : 13:57:14.916: isCheckUseful = false: current = 1603195034, lastSucces=1603194956
13:57:14 : 13:57:14.916: Ignore Check request - last check not that far in the past
13:57:19 : 13:57:19.905: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:57:19 : 13:57:19.915: isCheckUseful = false: current = 1603195039, lastSucces=1603194956
13:57:19 : 13:57:19.916: Ignore Check request - last check not that far in the past
13:57:24 : 13:57:24.908: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:57:24 : 13:57:24.919: isCheckUseful = false: current = 1603195044, lastSucces=1603194956
13:57:24 : 13:57:24.920: Ignore Check request - last check not that far in the past
13:57:29 : 13:57:29.951: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:57:29 : 13:57:29.959: isCheckUseful = false: current = 1603195049, lastSucces=1603194956
13:57:29 : 13:57:29.959: Ignore Check request - last check not that far in the past
13:57:34 : 13:57:34.910: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:57:34 : 13:57:34.917: isCheckUseful = false: current = 1603195054, lastSucces=1603194956
13:57:34 : 13:57:34.918: Ignore Check request - last check not that far in the past
13:57:39 : 13:57:39.906: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:57:39 : 13:57:39.913: isCheckUseful = false: current = 1603195059, lastSucces=1603194956
13:57:39 : 13:57:39.914: Ignore Check request - last check not that far in the past
13:57:44 : 13:57:44.910: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:57:44 : 13:57:44.923: isCheckUseful = false: current = 1603195064, lastSucces=1603194956
13:57:44 : 13:57:44.923: Ignore Check request - last check not that far in the past
13:57:49 : 13:57:49.906: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:57:49 : 13:57:49.915: isCheckUseful = false: current = 1603195069, lastSucces=1603194956
13:57:49 : 13:57:49.915: Ignore Check request - last check not that far in the past
13:57:54 : 13:57:54.910: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:57:54 : 13:57:54.918: isCheckUseful = false: current = 1603195074, lastSucces=1603194956
13:57:54 : 13:57:54.918: Ignore Check request - last check not that far in the past
13:57:59 : 13:57:59.907: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:57:59 : 13:57:59.915: isCheckUseful = false: current = 1603195079, lastSucces=1603194956
13:57:59 : 13:57:59.915: Ignore Check request - last check not that far in the past
13:58:04 : 13:58:04.911: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:58:04 : 13:58:04.917: isCheckUseful = false: current = 1603195084, lastSucces=1603194956
13:58:04 : 13:58:04.918: Ignore Check request - last check not that far in the past
13:58:09 : 13:58:09.908: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:58:09 : 13:58:09.914: isCheckUseful = false: current = 1603195089, lastSucces=1603194956
13:58:09 : 13:58:09.915: Ignore Check request - last check not that far in the past
13:58:14 : 13:58:14.912: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:58:14 : 13:58:14.921: isCheckUseful = false: current = 1603195094, lastSucces=1603194956
13:58:14 : 13:58:14.922: Ignore Check request - last check not that far in the past
13:58:19 : 13:58:19.908: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:58:19 : 13:58:19.917: isCheckUseful = false: current = 1603195099, lastSucces=1603194956
13:58:19 : 13:58:19.917: Ignore Check request - last check not that far in the past
13:58:24 : 13:58:24.912: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:58:24 : 13:58:24.918: isCheckUseful = false: current = 1603195104, lastSucces=1603194956
13:58:24 : 13:58:24.918: Ignore Check request - last check not that far in the past
13:58:29 : 13:58:29.908: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:58:29 : 13:58:29.915: isCheckUseful = false: current = 1603195109, lastSucces=1603194956
13:58:29 : 13:58:29.916: Ignore Check request - last check not that far in the past
13:58:34 : 13:58:34.916: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:58:34 : 13:58:34.923: isCheckUseful = false: current = 1603195114, lastSucces=1603194956
13:58:34 : 13:58:34.924: Ignore Check request - last check not that far in the past
13:58:39 : 13:58:39.909: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:58:39 : 13:58:39.915: isCheckUseful = false: current = 1603195119, lastSucces=1603194956
13:58:39 : 13:58:39.915: Ignore Check request - last check not that far in the past
13:58:44 : 13:58:44.914: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:58:44 : 13:58:44.936: isCheckUseful = false: current = 1603195124, lastSucces=1603194956
13:58:44 : 13:58:44.939: Ignore Check request - last check not that far in the past
13:58:49 : 13:58:49.910: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:58:49 : 13:58:49.915: isCheckUseful = false: current = 1603195129, lastSucces=1603194956
13:58:49 : 13:58:49.915: Ignore Check request - last check not that far in the past
13:58:54 : 13:58:54.915: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:58:54 : 13:58:54.922: isCheckUseful = false: current = 1603195134, lastSucces=1603194956
13:58:54 : 13:58:54.923: Ignore Check request - last check not that far in the past
13:58:59 : 13:58:59.910: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:58:59 : 13:58:59.915: isCheckUseful = false: current = 1603195139, lastSucces=1603194956
13:58:59 : 13:58:59.915: Ignore Check request - last check not that far in the past
13:59:04 : 13:59:04.915: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:59:04 : 13:59:04.921: isCheckUseful = false: current = 1603195144, lastSucces=1603194956
13:59:04 : 13:59:04.921: Ignore Check request - last check not that far in the past
13:59:09 : 13:59:09.912: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:59:09 : 13:59:09.916: isCheckUseful = false: current = 1603195149, lastSucces=1603194956
13:59:09 : 13:59:09.917: Ignore Check request - last check not that far in the past
13:59:14 : 13:59:14.916: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:59:14 : 13:59:14.920: isCheckUseful = false: current = 1603195154, lastSucces=1603194956
13:59:14 : 13:59:14.921: Ignore Check request - last check not that far in the past
13:59:19 : 13:59:19.912: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:59:19 : 13:59:19.917: isCheckUseful = false: current = 1603195159, lastSucces=1603194956
13:59:19 : 13:59:19.917: Ignore Check request - last check not that far in the past
13:59:24 : 13:59:24.916: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:59:24 : 13:59:24.921: isCheckUseful = false: current = 1603195164, lastSucces=1603194956
13:59:24 : 13:59:24.922: Ignore Check request - last check not that far in the past
13:59:29 : 13:59:29.914: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:59:29 : 13:59:29.918: isCheckUseful = false: current = 1603195169, lastSucces=1603194956
13:59:29 : 13:59:29.918: Ignore Check request - last check not that far in the past
13:59:34 : 13:59:34.949: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:59:34 : 13:59:34.953: isCheckUseful = false: current = 1603195174, lastSucces=1603194956
13:59:34 : 13:59:34.954: Ignore Check request - last check not that far in the past
13:59:39 : 13:59:39.912: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:59:39 : 13:59:39.922: isCheckUseful = false: current = 1603195179, lastSucces=1603194956
13:59:39 : 13:59:39.922: Ignore Check request - last check not that far in the past
13:59:44 : 13:59:44.917: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:59:44 : 13:59:44.922: isCheckUseful = false: current = 1603195184, lastSucces=1603194956
13:59:44 : 13:59:44.922: Ignore Check request - last check not that far in the past
13:59:49 : 13:59:49.914: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:59:49 : 13:59:49.922: isCheckUseful = false: current = 1603195189, lastSucces=1603194956
13:59:49 : 13:59:49.923: Ignore Check request - last check not that far in the past
13:59:54 : 13:59:54.918: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:59:54 : 13:59:54.923: isCheckUseful = false: current = 1603195194, lastSucces=1603194956
13:59:54 : 13:59:54.924: Ignore Check request - last check not that far in the past
13:59:59 : 13:59:59.915: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
13:59:59 : 13:59:59.920: isCheckUseful = false: current = 1603195199, lastSucces=1603194956
13:59:59 : 13:59:59.920: Ignore Check request - last check not that far in the past
14:00:04 : 14:00:04.918: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:00:04 : 14:00:04.923: isCheckUseful = false: current = 1603195204, lastSucces=1603194956
14:00:04 : 14:00:04.923: Ignore Check request - last check not that far in the past
14:00:09 : 14:00:09.915: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:00:09 : 14:00:09.919: isCheckUseful = false: current = 1603195209, lastSucces=1603194956
14:00:09 : 14:00:09.919: Ignore Check request - last check not that far in the past
14:00:14 : 14:00:14.915: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:00:14 : 14:00:14.919: isCheckUseful = false: current = 1603195214, lastSucces=1603194956
14:00:14 : 14:00:14.920: Ignore Check request - last check not that far in the past
14:00:20 : 14:00:20.251: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:00:20 : 14:00:20.257: isCheckUseful = false: current = 1603195220, lastSucces=1603194956
14:00:20 : 14:00:20.257: Ignore Check request - last check not that far in the past
14:00:25 : 14:00:25.260: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:00:25 : 14:00:25.265: isCheckUseful = false: current = 1603195225, lastSucces=1603194956
14:00:25 : 14:00:25.265: Ignore Check request - last check not that far in the past
14:00:30 : 14:00:30.258: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:00:30 : 14:00:30.261: isCheckUseful = false: current = 1603195230, lastSucces=1603194956
14:00:30 : 14:00:30.262: Ignore Check request - last check not that far in the past
14:00:31 : 14:00:31.105: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:00:31 : 14:00:31.108: isCheckUseful = false: current = 1603195231, lastSucces=1603194956
14:00:31 : 14:00:31.109: Ignore Check request - last check not that far in the past
14:00:36 : 14:00:36.104: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:00:36 : 14:00:36.110: isCheckUseful = false: current = 1603195236, lastSucces=1603194956
14:00:36 : 14:00:36.110: Ignore Check request - last check not that far in the past
14:00:41 : 14:00:41.150: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:00:41 : 14:00:41.157: isCheckUseful = false: current = 1603195241, lastSucces=1603194956
14:00:41 : 14:00:41.158: Ignore Check request - last check not that far in the past
14:00:46 : 14:00:46.104: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:00:46 : 14:00:46.108: isCheckUseful = false: current = 1603195246, lastSucces=1603194956
14:00:46 : 14:00:46.108: Ignore Check request - last check not that far in the past
14:00:51 : 14:00:51.108: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:00:51 : 14:00:51.113: isCheckUseful = false: current = 1603195251, lastSucces=1603194956
14:00:51 : 14:00:51.114: Ignore Check request - last check not that far in the past
14:00:56 : 14:00:56.105: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:00:56 : 14:00:56.112: isCheckUseful = false: current = 1603195256, lastSucces=1603194956
14:00:56 : 14:00:56.112: Ignore Check request - last check not that far in the past
14:01:01 : 14:01:01.110: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:01:01 : 14:01:01.114: isCheckUseful = false: current = 1603195261, lastSucces=1603194956
14:01:01 : 14:01:01.115: Ignore Check request - last check not that far in the past
14:01:06 : 14:01:06.171: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:01:06 : 14:01:06.176: isCheckUseful = false: current = 1603195266, lastSucces=1603194956
14:01:06 : 14:01:06.176: Ignore Check request - last check not that far in the past
14:01:11 : 14:01:11.110: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:01:11 : 14:01:11.114: isCheckUseful = false: current = 1603195271, lastSucces=1603194956
14:01:11 : 14:01:11.114: Ignore Check request - last check not that far in the past
14:01:16 : 14:01:16.104: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:01:16 : 14:01:16.108: isCheckUseful = false: current = 1603195276, lastSucces=1603194956
14:01:16 : 14:01:16.108: Ignore Check request - last check not that far in the past
14:01:21 : 14:01:21.110: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:01:21 : 14:01:21.115: isCheckUseful = false: current = 1603195281, lastSucces=1603194956
14:01:21 : 14:01:21.115: Ignore Check request - last check not that far in the past
14:01:26 : 14:01:26.145: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:01:26 : 14:01:26.149: isCheckUseful = false: current = 1603195286, lastSucces=1603194956
14:01:26 : 14:01:26.149: Ignore Check request - last check not that far in the past
14:01:26 : 14:01:26.364: Transferred POST-Data: {... "clientid":"ORD1","cmd":"signorders","value":"1;\"Eiskaffee\";3.90\n1;\"Pinocchio\";3.7\n1;\"Gemischtes Eis\";3.6"}
14:01:26 : 14:01:26.370: Starte Signierung
14:01:26 : com.secureflashcard.wormapi.WormException: WormException: WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST
14:01:26 :         at com.secureflashcard.wormapi.WormAPIJNI.WormStore_transaction_listStartedTransactions__SWIG_0(Native Method)
14:01:26 :         at com.secureflashcard.wormapi.WormStore.transaction_listStartedTransactions(WormStore.java:803)
14:01:26 :         at tseconnector.commands.TseCmdExecutor.completeUnfinishedTransactions(TseCmdExecutor.java:39)
14:01:26 :         at tseconnector.commands.TseSignCommand.signvalue(TseSignCommand.java:52)
14:01:26 :         at tseconnector.commands.TseSignCommand.doCmd(TseSignCommand.java:24)
14:01:26 :         at tseconnector.handler.RequestHandler.handle(RequestHandler.java:54)
14:01:26 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
14:01:26 :         at sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:83)
14:01:26 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:82)
14:01:26 :         at sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:675)
14:01:26 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
14:01:26 :         at sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:647)
14:01:26 :         at sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:158)
14:01:26 :         at sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:431)
14:01:26 :         at sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:396)
14:01:26 :         at java.lang.Thread.run(Thread.java:748)
14:01:30 : 14:01:30.639: Transferred POST-Data: {... "clientid":"ORD1","cmd":"signorders","value":"1;\"Eiskaffee\";3.90\n1;\"Pinocchio\";3.7\n1;\"Gemischtes Eis\";3.6"}
14:01:30 : 14:01:30.644: Starte Signierung
14:01:30 : com.secureflashcard.wormapi.WormException: WormException: WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST
14:01:30 :         at com.secureflashcard.wormapi.WormAPIJNI.WormStore_transaction_listStartedTransactions__SWIG_0(Native Method)
14:01:30 :         at com.secureflashcard.wormapi.WormStore.transaction_listStartedTransactions(WormStore.java:803)
14:01:30 :         at tseconnector.commands.TseCmdExecutor.completeUnfinishedTransactions(TseCmdExecutor.java:39)
14:01:30 :         at tseconnector.commands.TseSignCommand.signvalue(TseSignCommand.java:52)
14:01:30 :         at tseconnector.commands.TseSignCommand.doCmd(TseSignCommand.java:24)
14:01:30 :         at tseconnector.handler.RequestHandler.handle(RequestHandler.java:54)
14:01:30 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
14:01:30 :         at sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:83)
14:01:30 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:82)
14:01:30 :         at sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:675)
14:01:30 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
14:01:30 :         at sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:647)
14:01:30 :         at sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:158)
14:01:30 :         at sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:431)
14:01:30 :         at sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:396)
14:01:30 :         at java.lang.Thread.run(Thread.java:748)
14:01:31 : 14:01:31.580: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:01:31 : 14:01:31.585: isCheckUseful = false: current = 1603195291, lastSucces=1603194956
14:01:31 : 14:01:31.585: Ignore Check request - last check not that far in the past
14:01:33 : 14:01:33.287: Transferred POST-Data: {... "clientid":"ORD1","cmd":"signorders","value":"1;\"Eiskaffee\";3.90\n1;\"Pinocchio\";3.7\n1;\"Gemischtes Eis\";3.6"}
14:01:33 : 14:01:33.293: Starte Signierung
14:01:33 : com.secureflashcard.wormapi.WormException: WormException: WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST
14:01:33 :         at com.secureflashcard.wormapi.WormAPIJNI.WormStore_transaction_listStartedTransactions__SWIG_0(Native Method)
14:01:33 :         at com.secureflashcard.wormapi.WormStore.transaction_listStartedTransactions(WormStore.java:803)
14:01:33 :         at tseconnector.commands.TseCmdExecutor.completeUnfinishedTransactions(TseCmdExecutor.java:39)
14:01:33 :         at tseconnector.commands.TseSignCommand.signvalue(TseSignCommand.java:52)
14:01:33 :         at tseconnector.commands.TseSignCommand.doCmd(TseSignCommand.java:24)
14:01:33 :         at tseconnector.handler.RequestHandler.handle(RequestHandler.java:54)
14:01:33 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
14:01:33 :         at sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:83)
14:01:33 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:82)
14:01:33 :         at sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:675)
14:01:33 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
14:01:33 :         at sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:647)
14:01:33 :         at sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:158)
14:01:33 :         at sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:431)
14:01:33 :         at sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:396)
14:01:33 :         at java.lang.Thread.run(Thread.java:748)
14:01:36 : 14:01:36.115: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:01:36 : 14:01:36.121: isCheckUseful = false: current = 1603195296, lastSucces=1603194956
14:01:36 : 14:01:36.121: Ignore Check request - last check not that far in the past
14:01:41 : 14:01:41.111: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:01:41 : 14:01:41.116: isCheckUseful = false: current = 1603195301, lastSucces=1603194956
14:01:41 : 14:01:41.116: Ignore Check request - last check not that far in the past
14:01:46 : 14:01:46.108: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:01:46 : 14:01:46.112: isCheckUseful = false: current = 1603195306, lastSucces=1603194956
14:01:46 : 14:01:46.113: Ignore Check request - last check not that far in the past
14:01:51 : 14:01:51.111: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:01:51 : 14:01:51.116: isCheckUseful = false: current = 1603195311, lastSucces=1603194956
14:01:51 : 14:01:51.116: Ignore Check request - last check not that far in the past
14:01:56 : 14:01:56.108: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:01:56 : 14:01:56.113: isCheckUseful = false: current = 1603195316, lastSucces=1603194956
14:01:56 : 14:01:56.113: Ignore Check request - last check not that far in the past
14:02:01 : 14:02:01.113: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:02:01 : 14:02:01.118: isCheckUseful = false: current = 1603195321, lastSucces=1603194956
14:02:01 : 14:02:01.118: Ignore Check request - last check not that far in the past
14:02:06 : 14:02:06.109: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:02:06 : 14:02:06.113: isCheckUseful = false: current = 1603195326, lastSucces=1603194956
14:02:06 : 14:02:06.113: Ignore Check request - last check not that far in the past
14:02:11 : 14:02:11.113: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:02:11 : 14:02:11.116: isCheckUseful = false: current = 1603195331, lastSucces=1603194956
14:02:11 : 14:02:11.117: Ignore Check request - last check not that far in the past
14:02:16 : 14:02:16.109: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:02:16 : 14:02:16.114: isCheckUseful = false: current = 1603195336, lastSucces=1603194956
14:02:16 : 14:02:16.114: Ignore Check request - last check not that far in the past
14:02:21 : 14:02:21.117: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:02:21 : 14:02:21.122: isCheckUseful = false: current = 1603195341, lastSucces=1603194956
14:02:21 : 14:02:21.122: Ignore Check request - last check not that far in the past
14:02:26 : 14:02:26.110: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:02:26 : 14:02:26.118: isCheckUseful = false: current = 1603195346, lastSucces=1603194956
14:02:26 : 14:02:26.118: Ignore Check request - last check not that far in the past
14:02:31 : 14:02:31.138: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:02:31 : 14:02:31.141: isCheckUseful = false: current = 1603195351, lastSucces=1603194956
14:02:31 : 14:02:31.142: Ignore Check request - last check not that far in the past
14:02:36 : 14:02:36.111: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:02:36 : 14:02:36.115: isCheckUseful = false: current = 1603195356, lastSucces=1603194956
14:02:36 : 14:02:36.115: Ignore Check request - last check not that far in the past
14:02:41 : 14:02:41.115: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:02:41 : 14:02:41.118: isCheckUseful = false: current = 1603195361, lastSucces=1603194956
14:02:41 : 14:02:41.119: Ignore Check request - last check not that far in the past
14:02:46 : 14:02:46.111: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:02:46 : 14:02:46.116: isCheckUseful = false: current = 1603195366, lastSucces=1603194956
14:02:46 : 14:02:46.116: Ignore Check request - last check not that far in the past
14:02:51 : 14:02:51.116: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:02:51 : 14:02:51.120: isCheckUseful = false: current = 1603195371, lastSucces=1603194956
14:02:51 : 14:02:51.120: Ignore Check request - last check not that far in the past
14:02:56 : 14:02:56.112: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:02:56 : 14:02:56.116: isCheckUseful = false: current = 1603195376, lastSucces=1603194956
14:02:56 : 14:02:56.116: Ignore Check request - last check not that far in the past
14:03:01 : 14:03:01.116: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:03:01 : 14:03:01.120: isCheckUseful = false: current = 1603195381, lastSucces=1603194956
14:03:01 : 14:03:01.121: Ignore Check request - last check not that far in the past
14:03:06 : 14:03:06.113: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:03:06 : 14:03:06.117: isCheckUseful = false: current = 1603195386, lastSucces=1603194956
14:03:06 : 14:03:06.117: Ignore Check request - last check not that far in the past
14:03:11 : 14:03:11.116: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:03:11 : 14:03:11.122: isCheckUseful = false: current = 1603195391, lastSucces=1603194956
14:03:11 : 14:03:11.122: Ignore Check request - last check not that far in the past
14:03:16 : 14:03:16.113: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:03:16 : 14:03:16.117: isCheckUseful = false: current = 1603195396, lastSucces=1603194956
14:03:16 : 14:03:16.117: Ignore Check request - last check not that far in the past
14:03:21 : 14:03:21.118: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:03:21 : 14:03:21.122: isCheckUseful = false: current = 1603195401, lastSucces=1603194956
14:03:21 : 14:03:21.122: Ignore Check request - last check not that far in the past
14:03:26 : 14:03:26.114: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:03:26 : 14:03:26.120: isCheckUseful = false: current = 1603195406, lastSucces=1603194956
14:03:26 : 14:03:26.120: Ignore Check request - last check not that far in the past
14:03:31 : 14:03:31.153: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:03:31 : 14:03:31.158: isCheckUseful = false: current = 1603195411, lastSucces=1603194956
14:03:31 : 14:03:31.158: Ignore Check request - last check not that far in the past
14:03:36 : 14:03:36.115: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:03:36 : 14:03:36.121: isCheckUseful = false: current = 1603195416, lastSucces=1603194956
14:03:36 : 14:03:36.122: Ignore Check request - last check not that far in the past
14:03:41 : 14:03:41.119: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:03:41 : 14:03:41.125: isCheckUseful = false: current = 1603195421, lastSucces=1603194956
14:03:41 : 14:03:41.125: Ignore Check request - last check not that far in the past
14:03:46 : 14:03:46.117: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:03:46 : 14:03:46.121: isCheckUseful = false: current = 1603195426, lastSucces=1603194956
14:03:46 : 14:03:46.121: Ignore Check request - last check not that far in the past
14:03:51 : 14:03:51.119: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:03:51 : 14:03:51.123: isCheckUseful = false: current = 1603195431, lastSucces=1603194956
14:03:51 : 14:03:51.123: Ignore Check request - last check not that far in the past
14:03:56 : 14:03:56.135: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:03:56 : 14:03:56.139: isCheckUseful = false: current = 1603195436, lastSucces=1603194956
14:03:56 : 14:03:56.139: Ignore Check request - last check not that far in the past
14:04:01 : 14:04:01.120: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:04:01 : 14:04:01.123: isCheckUseful = false: current = 1603195441, lastSucces=1603194956
14:04:01 : 14:04:01.123: Ignore Check request - last check not that far in the past
14:04:06 : 14:04:06.117: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:04:06 : 14:04:06.121: isCheckUseful = false: current = 1603195446, lastSucces=1603194956
14:04:06 : 14:04:06.122: Ignore Check request - last check not that far in the past
14:04:11 : 14:04:11.121: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:04:11 : 14:04:11.124: isCheckUseful = false: current = 1603195451, lastSucces=1603194956
14:04:11 : 14:04:11.124: Ignore Check request - last check not that far in the past
14:04:16 : 14:04:16.118: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:04:16 : 14:04:16.121: isCheckUseful = false: current = 1603195456, lastSucces=1603194956
14:04:16 : 14:04:16.121: Ignore Check request - last check not that far in the past
14:04:21 : 14:04:21.121: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:04:21 : 14:04:21.124: isCheckUseful = false: current = 1603195461, lastSucces=1603194956
14:04:21 : 14:04:21.124: Ignore Check request - last check not that far in the past
14:04:26 : 14:04:26.118: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:04:26 : 14:04:26.122: isCheckUseful = false: current = 1603195466, lastSucces=1603194956
14:04:26 : 14:04:26.122: Ignore Check request - last check not that far in the past
14:04:31 : 14:04:31.145: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:04:31 : 14:04:31.149: isCheckUseful = false: current = 1603195471, lastSucces=1603194956
14:04:31 : 14:04:31.149: Ignore Check request - last check not that far in the past
14:04:36 : 14:04:36.118: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:04:36 : 14:04:36.123: isCheckUseful = false: current = 1603195476, lastSucces=1603194956
14:04:36 : 14:04:36.123: Ignore Check request - last check not that far in the past
14:04:41 : 14:04:41.124: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:04:41 : 14:04:41.127: isCheckUseful = false: current = 1603195481, lastSucces=1603194956
14:04:41 : 14:04:41.128: Ignore Check request - last check not that far in the past
14:04:46 : 14:04:46.120: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:04:46 : 14:04:46.124: isCheckUseful = false: current = 1603195486, lastSucces=1603194956
14:04:46 : 14:04:46.124: Ignore Check request - last check not that far in the past
14:04:51 : 14:04:51.123: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:04:51 : 14:04:51.127: isCheckUseful = false: current = 1603195491, lastSucces=1603194956
14:04:51 : 14:04:51.127: Ignore Check request - last check not that far in the past
14:04:56 : 14:04:56.120: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:04:56 : 14:04:56.124: isCheckUseful = false: current = 1603195496, lastSucces=1603194956
14:04:56 : 14:04:56.124: Ignore Check request - last check not that far in the past
14:05:01 : 14:05:01.123: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:05:01 : 14:05:01.127: isCheckUseful = false: current = 1603195501, lastSucces=1603194956
14:05:01 : 14:05:01.127: Ignore Check request - last check not that far in the past
14:05:06 : 14:05:06.120: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:05:06 : 14:05:06.123: isCheckUseful = false: current = 1603195506, lastSucces=1603194956
14:05:06 : 14:05:06.124: Ignore Check request - last check not that far in the past
14:05:11 : 14:05:11.125: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:05:11 : 14:05:11.129: isCheckUseful = false: current = 1603195511, lastSucces=1603194956
14:05:11 : 14:05:11.129: Ignore Check request - last check not that far in the past
14:05:16 : 14:05:16.122: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:05:16 : 14:05:16.124: isCheckUseful = false: current = 1603195516, lastSucces=1603194956
14:05:16 : 14:05:16.124: Ignore Check request - last check not that far in the past
14:05:21 : 14:05:21.125: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:05:21 : 14:05:21.128: isCheckUseful = false: current = 1603195521, lastSucces=1603194956
14:05:21 : 14:05:21.128: Ignore Check request - last check not that far in the past
14:05:26 : 14:05:26.122: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:05:26 : 14:05:26.127: isCheckUseful = false: current = 1603195526, lastSucces=1603194956
14:05:26 : 14:05:26.127: Ignore Check request - last check not that far in the past
14:05:31 : 14:05:31.152: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:05:31 : 14:05:31.155: isCheckUseful = false: current = 1603195531, lastSucces=1603194956
14:05:31 : 14:05:31.155: Ignore Check request - last check not that far in the past
14:05:36 : 14:05:36.124: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:05:36 : 14:05:36.127: isCheckUseful = false: current = 1603195536, lastSucces=1603194956
14:05:36 : 14:05:36.127: Ignore Check request - last check not that far in the past
14:05:41 : 14:05:41.127: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:05:41 : 14:05:41.130: isCheckUseful = false: current = 1603195541, lastSucces=1603194956
14:05:41 : 14:05:41.130: Ignore Check request - last check not that far in the past
14:05:46 : 14:05:46.123: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:05:46 : 14:05:46.127: isCheckUseful = false: current = 1603195546, lastSucces=1603194956
14:05:46 : 14:05:46.127: Ignore Check request - last check not that far in the past
14:05:51 : 14:05:51.127: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:05:51 : 14:05:51.130: isCheckUseful = false: current = 1603195551, lastSucces=1603194956
14:05:51 : 14:05:51.131: Ignore Check request - last check not that far in the past
14:05:55 : 14:05:55.011: Transferred POST-Data: {... "clientid":"ORD1","cmd":"signorders","value":"1;\"Eiskaffee\";3.90\n1;\"Pinocchio\";3.7\n1;\"Gemischtes Eis\";3.6"}
14:05:55 : 14:05:55.014: Starte Signierung
14:05:55 : com.secureflashcard.wormapi.WormException: WormException: WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST
14:05:55 :         at com.secureflashcard.wormapi.WormAPIJNI.WormStore_transaction_listStartedTransactions__SWIG_0(Native Method)
14:05:55 :         at com.secureflashcard.wormapi.WormStore.transaction_listStartedTransactions(WormStore.java:803)
14:05:55 :         at tseconnector.commands.TseCmdExecutor.completeUnfinishedTransactions(TseCmdExecutor.java:39)
14:05:55 :         at tseconnector.commands.TseSignCommand.signvalue(TseSignCommand.java:52)
14:05:55 :         at tseconnector.commands.TseSignCommand.doCmd(TseSignCommand.java:24)
14:05:55 :         at tseconnector.handler.RequestHandler.handle(RequestHandler.java:54)
14:05:55 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
14:05:55 :         at sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:83)
14:05:55 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:82)
14:05:55 :         at sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:675)
14:05:55 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
14:05:55 :         at sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:647)
14:05:55 :         at sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:158)
14:05:55 :         at sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:431)
14:05:55 :         at sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:396)
14:05:55 :         at java.lang.Thread.run(Thread.java:748)
14:05:58 : 14:05:58.146: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:05:58 : 14:05:58.150: isCheckUseful = false: current = 1603195558, lastSucces=1603194956
14:05:58 : 14:05:58.150: Ignore Check request - last check not that far in the past
14:06:01 : 14:06:01.234: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:06:01 : 14:06:01.240: isCheckUseful = false: current = 1603195561, lastSucces=1603194956
14:06:01 : 14:06:01.241: Ignore Check request - last check not that far in the past
14:06:06 : 14:06:06.139: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:06:06 : 14:06:06.149: isCheckUseful = false: current = 1603195566, lastSucces=1603194956
14:06:06 : 14:06:06.149: Ignore Check request - last check not that far in the past
14:06:11 : 14:06:11.126: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:06:11 : 14:06:11.130: isCheckUseful = false: current = 1603195571, lastSucces=1603194956
14:06:11 : 14:06:11.130: Ignore Check request - last check not that far in the past
14:06:15 : 14:06:15.331: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:06:15 : 14:06:15.335: isCheckUseful = false: current = 1603195575, lastSucces=1603194956
14:06:15 : 14:06:15.335: Ignore Check request - last check not that far in the past
14:06:20 : 14:06:20.345: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:06:20 : 14:06:20.348: isCheckUseful = false: current = 1603195580, lastSucces=1603194956
14:06:20 : 14:06:20.348: Ignore Check request - last check not that far in the past
14:06:25 : 14:06:25.348: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:06:25 : 14:06:25.351: isCheckUseful = false: current = 1603195585, lastSucces=1603194956
14:06:25 : 14:06:25.351: Ignore Check request - last check not that far in the past
14:06:30 : 14:06:30.345: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:06:30 : 14:06:30.348: isCheckUseful = false: current = 1603195590, lastSucces=1603194956
14:06:30 : 14:06:30.348: Ignore Check request - last check not that far in the past
14:06:35 : 14:06:35.333: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:06:35 : 14:06:35.336: isCheckUseful = false: current = 1603195595, lastSucces=1603194956
14:06:35 : 14:06:35.336: Ignore Check request - last check not that far in the past
14:06:40 : 14:06:40.344: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:06:40 : 14:06:40.347: isCheckUseful = false: current = 1603195600, lastSucces=1603194956
14:06:40 : 14:06:40.348: Ignore Check request - last check not that far in the past
14:06:45 : 14:06:45.350: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:06:45 : 14:06:45.353: isCheckUseful = false: current = 1603195605, lastSucces=1603194956
14:06:45 : 14:06:45.353: Ignore Check request - last check not that far in the past
14:06:50 : 14:06:50.345: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:06:50 : 14:06:50.348: isCheckUseful = false: current = 1603195610, lastSucces=1603194956
14:06:50 : 14:06:50.348: Ignore Check request - last check not that far in the past
14:06:55 : 14:06:55.349: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:06:55 : 14:06:55.352: isCheckUseful = false: current = 1603195615, lastSucces=1603194956
14:06:55 : 14:06:55.352: Ignore Check request - last check not that far in the past
14:07:00 : 14:07:00.334: Transferred POST-Data: {... "clientid":"ORD1","cmd":"signorders","value":"1;\"Eiskaffee\";3.90\n1;\"Pinocchio\";3.7\n1;\"Gemischtes Eis\";3.6"}
14:07:00 : 14:07:00.337: Starte Signierung
14:07:00 : com.secureflashcard.wormapi.WormException: WormException: WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST
14:07:00 :         at com.secureflashcard.wormapi.WormAPIJNI.WormStore_transaction_listStartedTransactions__SWIG_0(Native Method)
14:07:00 :         at com.secureflashcard.wormapi.WormStore.transaction_listStartedTransactions(WormStore.java:803)
14:07:00 :         at tseconnector.commands.TseCmdExecutor.completeUnfinishedTransactions(TseCmdExecutor.java:39)
14:07:00 :         at tseconnector.commands.TseSignCommand.signvalue(TseSignCommand.java:52)
14:07:00 :         at tseconnector.commands.TseSignCommand.doCmd(TseSignCommand.java:24)
14:07:00 :         at tseconnector.handler.RequestHandler.handle(RequestHandler.java:54)
14:07:00 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
14:07:00 :         at sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:83)
14:07:00 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:82)
14:07:00 :         at sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:675)
14:07:00 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
14:07:00 :         at sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:647)
14:07:00 :         at sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:158)
14:07:00 :         at sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:431)
14:07:00 :         at sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:396)
14:07:00 :         at java.lang.Thread.run(Thread.java:748)
14:07:04 : 14:07:04.953: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:07:04 : 14:07:04.956: isCheckUseful = false: current = 1603195624, lastSucces=1603194956
14:07:04 : 14:07:04.956: Ignore Check request - last check not that far in the past
14:07:05 : 14:07:05.350: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:07:05 : 14:07:05.353: isCheckUseful = false: current = 1603195625, lastSucces=1603194956
14:07:05 : 14:07:05.354: Ignore Check request - last check not that far in the past
14:07:10 : 14:07:10.403: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:07:10 : 14:07:10.407: isCheckUseful = false: current = 1603195630, lastSucces=1603194956
14:07:10 : 14:07:10.407: Ignore Check request - last check not that far in the past
14:07:15 : 14:07:15.338: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:07:15 : 14:07:15.341: isCheckUseful = false: current = 1603195635, lastSucces=1603194956
14:07:15 : 14:07:15.341: Ignore Check request - last check not that far in the past
14:07:18 : 14:07:18.388: Transferred POST-Data: {... "clientid":"ORD1","cmd":"signorders","value":"1;\"Eiskaffee\";3.90\n1;\"Pinocchio\";3.7\n1;\"Gemischtes Eis\";3.6"}
14:07:18 : 14:07:18.392: Starte Signierung
14:07:18 : com.secureflashcard.wormapi.WormException: WormException: WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST
14:07:18 :         at com.secureflashcard.wormapi.WormAPIJNI.WormStore_transaction_listStartedTransactions__SWIG_0(Native Method)
14:07:18 :         at com.secureflashcard.wormapi.WormStore.transaction_listStartedTransactions(WormStore.java:803)
14:07:18 :         at tseconnector.commands.TseCmdExecutor.completeUnfinishedTransactions(TseCmdExecutor.java:39)
14:07:18 :         at tseconnector.commands.TseSignCommand.signvalue(TseSignCommand.java:52)
14:07:18 :         at tseconnector.commands.TseSignCommand.doCmd(TseSignCommand.java:24)
14:07:18 :         at tseconnector.handler.RequestHandler.handle(RequestHandler.java:54)
14:07:18 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
14:07:18 :         at sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:83)
14:07:18 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:82)
14:07:18 :         at sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:675)
14:07:18 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
14:07:18 :         at sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:647)
14:07:18 :         at sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:158)
14:07:18 :         at sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:431)
14:07:18 :         at sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:396)
14:07:18 :         at java.lang.Thread.run(Thread.java:748)
14:14:51 : 14:14:51.966: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:14:51 : 14:14:51.969: isCheckUseful = false: current = 1603196091, lastSucces=1603194956
14:14:51 : 14:14:51.969: Ignore Check request - last check not that far in the past
14:14:53 : 14:14:53.947: Transferred POST-Data: {... "clientid":"ORD1","cmd":"signorders","value":"1;\"Eiskaffee\";3.90\n1;\"Pinocchio\";3.7\n1;\"Gemischtes Eis\";3.6"}
14:14:53 : 14:14:53.951: Starte Signierung
14:14:53 : com.secureflashcard.wormapi.WormException: WormException: WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST
14:14:53 :         at com.secureflashcard.wormapi.WormAPIJNI.WormStore_transaction_listStartedTransactions__SWIG_0(Native Method)
14:14:53 :         at com.secureflashcard.wormapi.WormStore.transaction_listStartedTransactions(WormStore.java:803)
14:14:53 :         at tseconnector.commands.TseCmdExecutor.completeUnfinishedTransactions(TseCmdExecutor.java:39)
14:14:53 :         at tseconnector.commands.TseSignCommand.signvalue(TseSignCommand.java:52)
14:14:53 :         at tseconnector.commands.TseSignCommand.doCmd(TseSignCommand.java:24)
14:14:53 :         at tseconnector.handler.RequestHandler.handle(RequestHandler.java:54)
14:14:53 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
14:14:53 :         at sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:83)
14:14:53 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:82)
14:14:53 :         at sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:675)
14:14:53 :         at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
14:14:53 :         at sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:647)
14:14:53 :         at sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:158)
14:14:53 :         at sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:431)
14:14:53 :         at sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:396)
14:14:53 :         at java.lang.Thread.run(Thread.java:748)
14:15:45 : 14:15:45.415: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
14:15:45 : 14:15:45.419: isCheckUseful = false: current = 1603196145, lastSucces=1603194956
14:15:45 : 14:15:45.420: Ignore Check request - last check not that far in the past
14:15:50 : 14:15:50.410: Transferred POST-Data: {... "clientid":"ORD1","cmd":"check"}
Ich habe mit Absicht derzeit nicht aktualisiert, da mir die TSE-Änderungen aussehen, dass sie neue Fehler bringen KÖNNTEN.
Ist das WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST dort schon berücktsichtigt gewesen oder tritt das vermutlich auf 2.0.10 auch noch auf?

André
Nach oben
pichel
Administrator
Beiträge: 1170
Registriert: So 13. Sep 2015, 19:48
Wohnort: Hamburg
Kontaktdaten:
Kontaktdaten von pichel

Re: BUG: TSE Connector

Beitrag von pichel »

Hallo André,

im Zuge der regelmäßigen Checks sollte der Fehler abgefangen sein, aber noch nicht bei fehlgeschlagenen Signierungen. Wobei ich mich frage, ob der Fehler nicht erst dann in diesem Fall auftreten sollte, wenn die TSE sowieso bereits einen Defekt hat, denn sonst sollte das regelmäßige Checken den Self Test ausreichend häufig aufrufen.

Aber ja, der Abfangen dieser Exception bei einer Signierung werde ich auch noch einbauen.

Gruß,

Stefan
Stefan Pichel
Entwickler der Kassensoftware OrderSprinter (http://www.ordersprinter.de)
Nach oben
pichel
Administrator
Beiträge: 1170
Registriert: So 13. Sep 2015, 19:48
Wohnort: Hamburg
Kontaktdaten:
Kontaktdaten von pichel

Re: BUG: TSE Connector

Beitrag von pichel »

Hallo,

ich habe eine verbesserte Version des TSEConnectors gebaut, diese könnte den WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST verhindern. Bisher hatte ich vor jedem Self Test ein Admin Login durchgeführt, um einen registerClient vornehmen zu können, denn ein Client muss vor jedem Self Test registriert sein und da gab es in der Vergangenheit mal einen berichteten Fehler. Das Admin-Login ist offenbar jedoch nicht in jedem Status erlaubt, so dass ich im Fehlerfall nun einen Self Test durchführe und darauf vertraue, dass der Client bereits registriert ist (das sollte eigentlich immer nach dem Setup bereits der Fall sein).

Hier ist die neue Version (entpacken und die jar ersetzen):

http://www.ordersprinter.de/bugfixes/tseconnector.zip

Hilft diese Version nun?

Gruß,

Stefan
Stefan Pichel
Entwickler der Kassensoftware OrderSprinter (http://www.ordersprinter.de)
Nach oben
Antworten

Zurück zu „Fragen“