BUG: TSE Connector

[os_user]

Hallo,
wir haben soeben im Produktivbetrieb einen Bug festgestellt, der wohl mit dem TSE-Connector in Zusammenhang steht:

- Wenn Artikel mit größer-Zeichen bzw. Klammer im Namen gebucht werden sollen hängt sich der Server auf. Der Artikel hat vorher schon exisitiert, also vermute ich einen Zusamenhang mit TSE.
- Wir verwenden OpenJDK und haben den TSE-Connector als systemd-service eingebunden. Manchmal stürzt die Anwendung nach folgendem Schema ab:

java[195953]: com.secureflashcard.wormapi.WormException: WormException: WORM_ERROR_NO_TIME_SET
java[195953]: #011at com.secureflashcard.wormapi.WormAPIJNI.WormStore_transaction_start(Native Method)
java[195953]: #011at com.secureflashcard.wormapi.WormStore.transaction_start(WormStore.java:706)
java[195953]: #011at tseconnector.commands.TseSignCommand.signvalue(TseSignCommand.java:54)
java[195953]: #011at tseconnector.commands.TseSignCommand.doCmd(TseSignCommand.java:26)
java[195953]: #011at tseconnector.handler.RequestHandler.handle(RequestHandler.java:51)
java[195953]: #011at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:77)
java[195953]: #011at jdk.httpserver/sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:82)
java[195953]: #011at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:80)
java[195953]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:692)
java[195953]: #011at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:77)
java[195953]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:664)
java[195953]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:159)
java[195953]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:442)
java[195953]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:408)
java[195953]: #011at java.base/java.lang.Thread.run(Thread.java:834)
java[195953]: {"msg":"WormException: WORM_ERROR_NO_TIME_SET","status":"ERROR"}

ein anderer Fehler, wenn der Connector über Nacht lief lautet:

java[25434]: com.secureflashcard.wormapi.WormException: WormException: WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST
java[25434]: #011at com.secureflashcard.wormapi.WormAPIJNI.WormStore_transaction_listStartedTransactions__SWIG_0(Native Met$
java[25434]: #011at com.secureflashcard.wormapi.WormStore.transaction_listStartedTransactions(WormStore.java:803)
java[25434]: #011at tseconnector.commands.TseCmdExecutor.completeUnfinishedTransactions(TseCmdExecutor.java:44)
java[25434]: #011at tseconnector.commands.TseSignCommand.signvalue(TseSignCommand.java:52)
java[25434]: #011at tseconnector.commands.TseSignCommand.doCmd(TseSignCommand.java:24)
java[25434]: #011at tseconnector.handler.RequestHandler.handle(RequestHandler.java:51)
java[25434]: #011at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:77)
java[25434]: #011at jdk.httpserver/sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:82)
java[25434]: #011at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:80)
java[25434]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:692)
java[25434]: #011at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:77)
java[25434]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:664)
java[25434]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:159)
java[25434]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:442)
java[25434]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:408)
java[25434]: #011at java.base/java.lang.Thread.run(Thread.java:834)
java[25434]: {"msg":"WormException: WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST","status":"ERROR"}

[pichel]

Hallo,

ich glaube eher nicht, dass es an den zu signierenden Daten liegt, aber ich werde das natürlich noch checken.

Beide Fehler sehen für mich so aus, dass die TSE nicht bereit ist, eine Signierung vorzunehmen, weil entweder
- Fall 1: die Uhrzeit der TSE wieder neu gesetzt werden muss, oder
- Fall 2: ein Self-Test erforderlich ist.

Beide Aktionen müssen regelmäßig vorgenommen werden und der TSEConnector sollte diese Fälle eigentlich selbstständig erkennen - was aber offenbar nicht zuverlässig funktioniert. Ich schaue mir die beide Fälle genauer an und werde versuchen, hierzu einen Bugfix zu liefern.

Bis daher könnte es vermutlich ausreichen, wenn man das System jeden morgen vor der ersten Buchung neu startet und somit die TSE initialisiert (alternativ: systemctl restart tseconnector).

Gruß,

Stefan

[os_user]

Hallo Herr Pichel,
anbei noch eine Fehlermeldung von heute Morgen, die vielleicht hilft. Scheinbar war das setzen der Zeit erfolgreich, aber ein anderer unbekannter Fehler lag vor:

java[198836]: Start Update Time with unixTime 1600842219
java[198836]: Logged in
java[198836]: Completed Update Time at TSE
java[198836]: com.secureflashcard.wormapi.WormException: WormException: WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST
java[198836]: #011at com.secureflashcard.wormapi.WormAPIJNI.WormStore_tse_registerClient(Native Method)
java[198836]: #011at com.secureflashcard.wormapi.WormStore.tse_registerClient(WormStore.java:547)
java[198836]: #011at tseconnector.commands.BaseTseCommand.registerClient(BaseTseCommand.java:58)
java[198836]: #011at tseconnector.commands.BaseTseCommand.makeTseReady(BaseTseCommand.java:47)
java[198836]: #011at tseconnector.commands.TseSignCommand.signvalue(TseSignCommand.java:41)
java[198836]: #011at tseconnector.commands.TseSignCommand.doCmd(TseSignCommand.java:26)
java[198836]: #011at tseconnector.handler.RequestHandler.handle(RequestHandler.java:51)
java[198836]: #011at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:77)
java[198836]: #011at jdk.httpserver/sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:82)
java[198836]: #011at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:80)
java[198836]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:692)
java[198836]: #011at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:77)
java[198836]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:664)
java[198836]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:159)
java[198836]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:442)
java[198836]: #011at jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:408)
java[198836]: #011at java.base/java.lang.Thread.run(Thread.java:834)
java[198836]: {"msg":"TSE not ready","status":"ERROR"}

Wir werden nun versuchen, ob ein morgendlicher Neustart hilft.

[pichel]

Hallo,

ja das ist die gleiche Baustelle. Die TSE verlangt regelmäßig die Durchführung eines Selbsttests und das Synchronisieren der Uhrzeit und das natürlich in der richtigen Reihenfolge. Eigentlich dachte ich, dass ich das alles richtig implementiert habe, aber die Exceptions widerlegen das leider. Ich muss mich also nochmal eingehend mit meinem Javacode befassen und das kostet Zeit, die mir gerade fehlt, um sofort einen Bugfix zu liefern. Ein paar Tage wird es dauern, ich schätze bis zu 2 Wochen..

Als Workaround sollte daher ein Restart des TSEConnectors vor Beginn der Arbeit helfen, denn dabei wird auf jedenfall ein Selbsttest und eine Zeitsynchronisierung vorgenommen.

Tut mir leid, dass die Fehler jetzt auffallen. Leider ist dieser Forums-Thread der erste, bei dem ich überhaupt Feedback zum TSEConnector bekommen habe. Und nun bleibt wenig Zeit bis zum Auslaufen der Nichtbeanstandungsregelung, aber ich werde trotzdem versuchen, den Bug noch rechtzeitig zu fixen.

Gruß,

Stefan

[os_user]

Sehr geehrter Herr Pichel,
ist wirklich eine Kleinigkeit, mit dem Neustart funktioniert alles wunderbar und der TSE-Connector läuft ansonsten sehr stabil. Die Implementierung als eigenes Modul ist übrigens spitzen, da das alles sehr flexibel macht. Und wirklich nochmals großes Kompliment für Ihre Leistung!

[pichel]

Hallo,

ich habe eine neue TSEConnector-Version erstellt, die die Notwendigkeit täglicher Neustarts eigentlich nun verhindern sollte. Mag das jemand testen und mir Feedback geben?

Hier kann man die Version downloaden:

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

Wenn mir in den nächsten Tagen keine Fehler berichtet werden, werde ich den verbesserten TSEConnector mit einer zukünftigen 2.0.6 veröffentlichen.

Gruß,

Stefan

[os_user]

Hallo Herr Pichel,
der neue TSE-Connector ist installiert. Sollte es einen Fehler geben werde ich diesen hier posten.

Danke und Gruß

[pichel]

Hallo,

der TSEConnector hat leider noch ein paar andere Kinderkrankheiten wie ich leider feststellen musste. Allerdings brauche ich noch ein paar Tage, bis diese gelöst sind und ich eine 2.0.6 herausbringen kann, in der das dann hoffentlich alles gelöst ist...

Gruß,

Stefan

[os_user]

Hallo,
leider wird der neue TSEConnector im Programm nicht richtig erkannt (oben erscheint neben Kasse das durchgestrichene TSE-Symbol). Alledings kann aus dem Admin ein Selbsttest angestoßen werden, der auch im syslog korrekt durchlaufen wird. Wir stellen zurück auf den mit 2.0.5 mitgelieferten TSEConnector.

Gruß

[pichel]

Hallo,

nun ja, erkannt werden hätte er schon sollen. An der Stelle (ping-Requesthandler) hatte ich keine Änderung vorgenommen und es hatte bei mir auch im Test funktioniert. Wie auch immer bastel ich zur Zeit an der 2.0.6, in der ein an vielen Stellen überarbeiteter TSEConnector enthalten sein wird. Leider dauert das aber noch ein paar Tage, bis ich die neue Version releasen kann. Etwas Geduld...

Gruß,

Stefan