Morgendliche Startschwierigkeiten der TSE

[pichel]

Hallo,

ich fürchte, es ist folgendes passiert:
- Aufruf der Adminoberfläche und Änderung der TSE-PIN/PUK
- TSE-Setup ausgeführt
- Neuaufruf der Verwaltungsansicht
- TSE-Anbindung auf Ja gesetzt.

Bis 2.0.9 wurden die per TSE-Setup gesetzten Daten nicht in der DB gespeichert, so dass beim Neuaufruf der Verwaltungsansicht wieder die alten PIN/PUK drinstanden und nach Aktivierung der TSE-Anbindung alle weiteren Aktionen (z.B. die regelmäßigen Checks auf Notwendigkeit von Self Test und Time Sync) die falsche, also nicht die für den TSE-Setup verwendete, PIN verwendet wurde.

In der 2.0.10, die ich gerade veröffentlicht habe, habe ich das nun verbessert. Nach einem Klick auf TSE-Setup werden die Daten auch in der Datenbank gespeichert. Ich habe zudem die Anleitung so angepasst, dass darin auch die richtige Reihenfolge der Erstinstallation beschrieben ist.

Im Fall von Florian ist es nun so, dass die TSE nicht mehrfach geSETUPt werden darf und das checke ich in der Software auch ab, indem ich die TSE vor einem Setup frage, ob sie schon eingerichtet wurde. Sollte aber die in der Admin-Overfläche noch eingestellte PIN anders als die für das TSE-Setup verwendete PIN sein, so kann der Selbsttest nicht erfolgreich durchlaufen, denn dazu muss man die ClientID bei der TSE registrieren, wozu man aber wieder die richtige PIN benötigt. Florian, bitte überprüfe doch mal, ob die aktuell eingestellte PIN auch wirklich die war, die du für das TSE-Setup verwendet hast und ändere sie gegegenfalls. Anschließend muss der TSEConnector neu gestartet werden.

Außerdem habe ich die Vermutung, dass sich nicht alle TSE gleich verhalten. Daher führt der TSEConnector in Version 2.0.9 nun vor wichtigen Funktionen wie Selbsttest, Time Sync usw. explizit ein Admin-Login durch.

Vielleicht konnte ich durch die Änderungen in 2.0.10 noch etwas mehr Stabilität erreichen.

Gruß,

Stefan

[Florian]

Moinsen,

ich bin mir ziemlich sicher dass es die PIN und PUK sind, die ich auch am Anfang beim ersten Einrichten eingestellt habe.
Die erste hier installierte Version war 2.0.5, da gab es in der Tat ein Problem mit dem Speichern der geänderten PIN/PUK, das hatte ich aber bemerkt und berücksichtigt (ich weiss nicht mehr genau wie, entweder per Klick auf "Speichern" oder, weil das auch nicht ging, direkt in die db geschrieben), leider im Stress vergessen diesen Bug zu melden...

Nachdem ich gerade auf die aktuelle Version 2.0.10 aktualisiert habe gibt es zwar zuerst mal wieder eine freundliche WormException, das Problem scheint aber auf den ersten Blick behoben zu sein.
Das Log sieht nun so aus (der erste Start nach dem Aktualisieren, ohne vorher das TSE-Setup auszuführen)

Code: Alles auswählen

 TSE seems to be mounted
 Sync Time = 1800 seconds (30 minutes)
 2020-10-17T09:43:20.887035: Abgeschlossen Startup des TSEConnectors
 2020-10-17T09:43:25.448918: Transferred POST-Data: {"pass":"***","pin":[***],"clientid":"ORD1","cmd":"check"}
 2020-10-17T09:43:25.757617: isCheckUseful = true: current = 1602920605, lastSucces=0
 2020-10-17T09:43:25.757734: Check for TSE Status and availability
 com.secureflashcard.wormapi.WormException: WormException: WORM_ERROR_RESPONSE_MISSING
         at com.secureflashcard.wormapi.WormAPIJNI.WormStore_user_login(Native Method)
         at com.secureflashcard.wormapi.WormStore.user_login(WormStore.java:600)
         at tseconnector.commands.TseAdminCommand.check(TseAdminCommand.java:406)
         at tseconnector.commands.TseAdminCommand.doCmd(TseAdminCommand.java:65)
         at tseconnector.handler.RequestHandler.handle(RequestHandler.java:54)
         at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:77)
         at jdk.httpserver/sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:82)
         at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:80)
         at jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:692)
         at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:77)
         at jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:664)
         at jdk.httpserver/sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:159)
         at jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:442)
         at jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:408)
         at java.base/java.lang.Thread.run(Thread.java:834)
 2020-10-17T09:43:30.433363: Transferred POST-Data: {"pass":"***","pin":[***],"clientid":"ORD1","cmd":"check"}
 2020-10-17T09:43:30.441819: isCheckUseful = true: current = 1602920610, lastSucces=0
 2020-10-17T09:43:30.442056: Check for TSE Status and availability
 2020-10-17T09:43:30.640666: TSE has no valid time. Set time now.
 2020-10-17T09:43:30.640854: TSE needs time sync because soon expiration of maxSyncTime after last time sync
 2020-10-17T09:43:30.995512: TSE time is set
 2020-10-17T09:43:31.399232: TSE time is set
 2020-10-17T09:43:35.432370: Transferred POST-Data: {"pass":"***","pin":[***],"clientid":"ORD1","cmd":"check"}
 2020-10-17T09:43:35.440597: isCheckUseful = false: current = 1602920615, lastSucces=1602920611
 2020-10-17T09:43:35.440824: Ignore Check request - last check not that far in the past
 2020-10-17T09:43:40.440854: Transferred POST-Data: {"pass":"***","pin":[***],"clientid":"ORD1","cmd":"check"}
 2020-10-17T09:43:40.448604: isCheckUseful = false: current = 1602920620, lastSucces=1602920611
 2020-10-17T09:43:40.448818: Ignore Check request - last check not that far in the past
 2020-10-17T09:43:45.439897: Transferred POST-Data: {"pass":"***","pin":[***],"clientid":"ORD1","cmd":"check"}
 2020-10-17T09:43:45.447727: isCheckUseful = false: current = 1602920625, lastSucces=1602920611
 2020-10-17T09:43:45.447991: Ignore Check request - last check not that far in the past
 2020-10-17T09:43:50.441030: Transferred POST-Data: {"pass":"***","pin":[***],"clientid":"ORD1","cmd":"check"}
...es geht so weiter :)

Ich werde das weiter beobachten und noch einmal Rückmeldung geben (hoffentlich eine positive).

Erst einmal vielen Dank an alle!

Gruß,
Florian

[pichel]

Hallo Florian,

die Meldung mit der WORM_RESPONSE_MISSING kenne ich noch nicht, aber ich nehme an, dieser ergibt daher, dass die TSE im Low Energy Modus in der Nacht gegangen ist, da der TSConnector kein regelmäßiges updateTime aufruft, wenn niemand in der Kernapplikation angemeldet ist. In der Doku heißt es zum Thema Zeitsynchronisierung:

Note: It is strongly recommended to call this method at the frequency
announced in WormInformation.maxTimeSynchronizationDelay().
Otherwise, the TSE will enter a low power mode and will (with very low
probability) return an error code on the next attempt of calling this
method (or any other method that interacts with the CSP).
After having received the error, running the self test is required to
remedy the situation.

Der TSEConnector reagiert darauf mit einem SelfTest oder was jeweils die TSE sagt, dass sie jetzt brauche. Wenn also das der einzige morgentliche Fehler bleibt, bin ich zufrieden...

Ach ja, es kann sein, dass du das Logging wieder auf 1 oder 0 zurücksetzen musst, es gibt da einen maximalen Buffer der cmd.

Gruß,

Stefan

[Florian]

Hallo Stefan,

der Rechner wird abends heruntergefahren und schaltet sich morgens auch automatisch wieder ein um Strom zu sparen, insofern läuft da nachts eh nichts.

Mir ist dieser Fehler auch sehr viel lieber als das vorherige Verhalten, insofern vielen Dank für die neue Version
Am Montag weiss ich dann, ob er auch nach einer ausgeschalteten Nacht auftritt.
Heute wurden auf jeden Fall Verkäufe und ein Tagesabschluss gemacht und alles lief anscheinend soweit problemlos.

Mit "cmd" meinst du wahrscheinlich irgendetwas Windows-spezifisches vermute ich?
Ich habe hier nur GNU/Linux im Einsatz, da gibt es meines Wissens nach keinerlei Probleme mit "zu viel logging".

Allerdings dazu noch eine Beobachtung: Es kam im journal nichts vom erweiterten logging des connectors an, als ich die systemd Service-Datei noch wie in der Anleitung beschrieben (oder war es im Installationsskript?) im Einsatz hatte. Erst als ich vom Type "fork" auf "simple" umgestellt und entsprechend das "&" am Ende des Befehls entfernt hatte, damit er im Vordergrund läuft, waren die geschwätzigen Zeilen dort zu sehen.

Gruß,
Florian

[Florian]

Moin,

nachdem der Rechner nun seit Samstag ausgeschaltet war gibt es heute morgen leider neue Probleme.

Code: Alles auswählen

 2020-10-19T09:34:10.770677: Transferred POST-Data: {"pass":"***","pin":[***],"clientid":"ORD1","cmd":"check"}
 2020-10-19T09:34:10.775657: isCheckUseful = true: current = 1603092850, lastSucces=0
 2020-10-19T09:34:10.775842: Check for TSE Status and availability
 com.secureflashcard.wormapi.WormException: WormException: WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST
         at com.secureflashcard.wormapi.WormAPIJNI.WormStore_user_login(Native Method)
         at com.secureflashcard.wormapi.WormStore.user_login(WormStore.java:600)
         at tseconnector.commands.TseAdminCommand.check(TseAdminCommand.java:406)
         at tseconnector.commands.TseAdminCommand.doCmd(TseAdminCommand.java:65)
         at tseconnector.handler.RequestHandler.handle(RequestHandler.java:54)
         at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:77)
         at jdk.httpserver/sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:82)
         at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:80)
         at jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:692)
         at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:77)
         at jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:664)
         at jdk.httpserver/sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:159)
         at jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:442)
         at jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:408)
         at java.base/java.lang.Thread.run(Thread.java:834)

Die Antwort auf einen manuell erzwungenen Selbsttest ist ebenfalls eine WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST Exception.

In Version 2.0.9 half es ja wie schon geschrieben, erneut das TSE-Setup durchzuführen, danach konnte dann anscheinend die Zeit korrekt gesetzt werden und die TSE war den Tag über einsatzbereit bis am nächsten morgen nach einigen Stunden ausgeschaltetem Rechner das Spiel von vorne los ging.
Das klappte und auch wenn das TSE-Setup nur einmal ausgeführt werden sollte und dieses Vorgehen eigentlich keinerlei Auswirkungen haben sollte da der Connector überprüft ob die TSE bereits eingerichtet wurde hat es dennoch dazu geführt, dass die Zeit korrekt gesetzt werden konnte und die TSE arbeitete. Das Aufrufen des TSE-Setup hat nun eine andere Antwort zur Folge als in Version 2.0.9:

Code: Alles auswählen

2020-10-19T10:46:27.868859: Transferred POST-Data: {"pass":"***","pin":[***],"puk":[***],"clientid":"ORD1","cmd":"setup"}
 2020-10-19T10:46:27.871223: TSE was already intialized - setup not done
 2020-10-19T10:46:27.871305: Start InfoTask
 2020-10-19T10:46:27.877719: Completed InfoTask. Out=CommandResult [ok=true, msg={"msg":"Init state = WORM_INIT_INITIALIZED.TSE was already intialized - setup not done"}]
 CommandResult [ok=true, msg={"msg":"TseDescription: ***\nceritificateExpirationDate: ***\nCreated Signatures: ***\nhasValidTime: false\nAnzahl verbleibender Signaturen: ***\n"}]

Und es hilft leider auch nicht mehr, danach geht es mit den WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST Exceptions im Log weiter und die TSE ist weiterhin nicht einsatzbereit.

Gruß,
Florian

[pichel]

Hallo Florian,

zeig doch mal die Ausgabe, wenn du nur einen Self Test startest, nicht TSE-Setup und auch nicht das regelmäßige Check. D.h.

1. TSE-Anbindung auf Nein
2. Self Test auswählen und auf "-> TSE" klicken
3. Ausgabe von TSEConnector

Gruß,

Stefan

[Florian]

Hallo Stefan,

Code: Alles auswählen

Command: forceselftest

ERROR: Self test Exception: WormException: WORM_ERROR_WRONG_STATE_NEEDS_SELF_TEST

Gruß,
Florian

[pichel]

Hallo Florian,

also wenn der Self Test schon mit einem solchen Fehler zurückkommt, könnte man sogar auf die Idee kommen, dass die TSE selbst kaputt ist.

Ich schlage vor, dass du das beim Anbieter meldest. Für die Swissbit-TSE gibt es das SDK, welches auch Tools enthält, mit denen man bestimmte Aktionen über ein GUI steuern kann. Ich würde es ja bereitstellen, aber bin mir nicht sicher, ob ich damit nicht gegen die Lizenzbedingungen verstoßen würde. Deswegen ist es besser, wenn der Anbieter die TSE entweder austauscht oder dir den Zugang zum SDK gibt und du den Selbsttest über deren Beispielimplantierung anstößt.

Gruß,

Stefan

[Florian]

Hallo Stefan,

das habe ich getan. Bin gespannt was da zurückkommt.

Gruß,
Florian

[Florian]

Hallo Stefan,

die Technik-Abteilung hat bis jetzt sinngemäss geschrieben, dass man mit Hilfe des "wormcli" aus dem SDK Packet den genauen Status der TSE ermitteln kann. Diese Information hätte der Techniker gerne, um den Fall beurteilen zu können und er mutmaßt, dass durch falsche PIN und PUK Handhabung die TSE nicht mehr erreichbar ist.

Leider gab es bis jetzt noch keine Antwort wie ich denn an das CLI gelangen kann, ich warte noch.

In der Zwischenzeit habe ich einmal testweise wieder auf deine alte Connector-Version umgestellt, dort ist der manuelle Selbsttest (ausgeführt so wie du es beschrieben hast) erfolgreich durchgelaufen:

Code: Alles auswählen

Command: forceselftest

Result: Self Test completed

Nachdem ich dann wieder auf die neue Connector-Version umgestellt hatte, läuft auch dort der Selbsttest durch (ohne nächtliches Ausschalten dazwischen, und auch ohne das TSE-Setup ausgeführt zu haben).

Auch war es ja in den letzten Tagen der TSE ja immer möglich, Signaturen zu erstellen wenn die Zeit korrekt war (solange der Rechner nicht über Nacht ausgeschaltet wurde funktioniert das zuverlässig).
Das bedeutet ja auch, dass die TSE sehr wohl "erreichbar" ist und auch arbeitet. Dieses Verhalten würde ich eigentlich mal komplett ausschliessen wenn tatsächlich die PIN nicht korrekt wäre, oder?

Gruß,
Florian