2018-01-25 09:53:03,626 [main] INFO o.o.richclient.LogbackConfig:81 - Configured Logback with config file from: /home/alexander/.openecard/richclient_logback.xml 2018-01-25 09:53:03,653 [main] WARN org.openecard.common.I18n:152 - Failed to load resource ifd for lang C. 2018-01-25 09:53:03,653 [main] WARN org.openecard.common.I18n:152 - Failed to load resource ifd for lang de. 2018-01-25 09:53:03,654 [main] WARN org.openecard.common.I18n:152 - Failed to load resource ifd for lang de_DE. 2018-01-25 09:53:03,657 [main] WARN org.openecard.common.I18n:152 - Failed to load resource sal for lang C. 2018-01-25 09:53:03,657 [main] WARN org.openecard.common.I18n:152 - Failed to load resource sal for lang de. 2018-01-25 09:53:03,657 [main] WARN org.openecard.common.I18n:152 - Failed to load resource sal for lang de_DE. 2018-01-25 09:53:03,659 [main] WARN org.openecard.common.I18n:152 - Failed to load resource richclient for lang de_DE. 2018-01-25 09:53:03,664 [main] INFO org.openecard.richclient.RichClient:122 - Starting Open eCard App org.openecard.common.SemanticVersion@e580929 ... 2018-01-25 09:53:04,966 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:107 - Loading middleware config. 2018-01-25 09:53:04,967 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:144 - Reading middleware config from XML file. 2018-01-25 09:53:05,037 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:158 - CardImageName: rub-card.png 2018-01-25 09:53:05,039 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:158 - CardImageName: luxtrust-v3.jpg 2018-01-25 09:53:05,041 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:158 - CardImageName: Lux-eID.jpg 2018-01-25 09:53:05,042 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:158 - CardImageName: ihk-card.jpg 2018-01-25 09:53:05,050 [main] WARN org.openecard.common.I18n:152 - Failed to load resource recognition for lang de_DE. 2018-01-25 09:53:05,136 [Init-File-Addons] DEBUG org.openecard.addon.FileRegistry:144 - Starting addon filesystem monitor on path: /home/alexander/.openecard/addons 2018-01-25 09:53:05,139 [main] WARN org.openecard.common.I18n:152 - Failed to load resource http for lang de_DE. 2018-01-25 09:53:05,152 [main] DEBUG o.o.c.binding.http.HttpService:77 - Starting HTTPBinding on port 24727 2018-01-25 09:53:05,173 [main] DEBUG o.o.c.binding.http.HttpService:88 - Add handler [org.openecard.control.binding.http.handler.HttpAppPluginActionHandler] for ID [*] 2018-01-25 09:53:05,477 [Init-Classpath-Addons] INFO o.openecard.addon.ClasspathRegistry:94 - Loaded internal TR-03112 add-on. 2018-01-25 09:53:05,498 [Init-Classpath-Addons] INFO o.openecard.addon.ClasspathRegistry:94 - Loaded internal ChipGateway add-on. 2018-01-25 09:53:05,512 [Init-Classpath-Addons] INFO o.openecard.addon.ClasspathRegistry:94 - Loaded internal PIN-Management add-on. 2018-01-25 09:53:05,516 [Init-Classpath-Addons] INFO o.openecard.addon.ClasspathRegistry:94 - Loaded internal GenericCrypto add-on. 2018-01-25 09:53:05,522 [Init-Classpath-Addons] INFO o.openecard.addon.ClasspathRegistry:94 - Loaded internal Status add-on. 2018-01-25 09:53:05,523 [Init-Classpath-Addons] WARN o.openecard.addon.ClasspathRegistry:89 - Skipped loading internal add-on PKCS#11, because it is not available. 2018-01-25 09:53:05,977 [main] DEBUG o.o.ifd.event.IfdEventRunner:91 - Requesting terminal names. 2018-01-25 09:53:06,001 [main] DEBUG org.openecard.scio.PCSCTerminals:99 - No reader available exception. 2018-01-25 09:53:06,002 [main] DEBUG o.o.ifd.event.IfdEventRunner:97 - Requesting status for all terminals found. 2018-01-25 09:53:06,017 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:220 - No reader available exception. 2018-01-25 09:53:06,021 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:07,522 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:09,023 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:10,525 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:12,026 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:13,528 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:15,030 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:16,531 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:18,032 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:19,534 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:20,442 [AWT-EventQueue-1] DEBUG o.openecard.richclient.gui.Status$2:179 - About button pressed. 2018-01-25 09:53:20,453 [AWT-EventQueue-1] WARN org.openecard.common.I18n:152 - Failed to load resource about for lang de_DE. 2018-01-25 09:53:21,035 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:22,536 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:24,038 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:25,540 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:27,042 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:28,543 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:30,045 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:31,547 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:33,048 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:34,549 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:36,051 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:37,552 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:39,054 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:40,555 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:42,056 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:43,557 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:45,059 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:46,560 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:48,061 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:49,563 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:51,064 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:52,566 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:54,067 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:55,569 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:57,070 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:53:58,572 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:00,073 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:01,574 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:03,076 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:04,577 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:06,078 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:07,579 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:09,081 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:10,582 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:12,084 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:13,585 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:15,086 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:16,588 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:18,089 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:19,591 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:21,092 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:22,594 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:24,095 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:25,596 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:27,098 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:28,599 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:30,101 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:31,602 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:33,103 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:34,605 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:36,106 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:37,608 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:39,109 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:40,611 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:42,112 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:43,614 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:45,115 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:46,616 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:48,118 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:49,619 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:51,121 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:52,622 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:54,123 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:55,624 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:57,126 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:54:58,627 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:00,128 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:01,629 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:03,130 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:04,632 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:06,132 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:07,633 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:09,135 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:10,636 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:12,138 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:13,639 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:15,140 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:16,642 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:18,143 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:19,644 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:21,145 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:22,647 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:24,149 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:25,650 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:27,151 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:28,652 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:30,154 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:31,655 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:33,156 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:34,658 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:36,159 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:37,661 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:39,162 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:40,664 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:42,165 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:43,667 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:45,168 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:46,670 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:48,171 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:49,673 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:51,174 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:52,675 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:54,177 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:55,678 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:57,180 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:55:58,681 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:412 - Waiting for PCSC system to become available again. 2018-01-25 09:56:00,194 [IFD Watcher 0] DEBUG o.o.common.util.HandlerUtils:131 - Found ContextHandle in object of type GetIFDCapabilities. 2018-01-25 09:56:00,203 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:00,203 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:00,204 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.GetIFDCapabilities 2018-01-25 09:56:00,219 [IFD Watcher 0] DEBUG org.openecard.ifd.scio.IFD:350 - Failed to request status from terminal. org.openecard.common.ifd.scio.SCIOException: Reader refused to connect card with any protocol. at org.openecard.ifd.scio.wrapper.SingleThreadChannel.connectCard(SingleThreadChannel.java:139) at org.openecard.ifd.scio.wrapper.SingleThreadChannel.(SingleThreadChannel.java:80) at org.openecard.ifd.scio.wrapper.ChannelManager.openMasterChannel(ChannelManager.java:90) at org.openecard.ifd.scio.IFD.getIFDCapabilities(IFD.java:285) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.openecard.transport.dispatcher.Service.invoke(Service.java:192) at org.openecard.transport.dispatcher.MessageDispatcher.deliver(MessageDispatcher.java:116) at org.openecard.transport.dispatcher.MessageDispatcher.safeDeliver(MessageDispatcher.java:135) at org.openecard.ifd.event.IfdEventRunner.getCapabilities(IfdEventRunner.java:279) at org.openecard.ifd.event.IfdEventRunner.fireEvents(IfdEventRunner.java:189) at org.openecard.ifd.event.IfdEventRunner.run(IfdEventRunner.java:128) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2018-01-25 09:56:00,228 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:00,229 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:00,229 [IFD Watcher 0] DEBUG o.o.ifd.event.IfdEventRunner:201 - Found a terminal added event (REINER SCT cyberJack RFID standard (0810057893) 00 00). 2018-01-25 09:56:00,231 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:361 - Event: TERMINAL_ADDED 2018-01-25 09:56:00,232 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:369 - ConnectionHandle: iso.std.iso_iec._24727.tech.schema.ConnectionHandleType@57fec3f8 2018-01-25 09:56:00,232 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:371 - RecognitionInfo: null 2018-01-25 09:56:00,232 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:373 - IFDName: REINER SCT cyberJack RFID standard (0810057893) 00 00 2018-01-25 09:56:00,234 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event TERMINAL_ADDED into event queue. 2018-01-25 09:56:00,236 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:201 - Detecting initial terminal status. 2018-01-25 09:56:00,237 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:205 - Terminal='REINER SCT cyberJack RFID standard (0810057893) 00 00' cardPresent=false 2018-01-25 09:56:28,837 [SCIO Watcher 0] INFO o.o.i.s.wrapper.SingleThreadChannel:144 - Card connected with protocol T=1. 2018-01-25 09:56:28,839 [IFD Watcher 0] DEBUG o.o.common.util.HandlerUtils:131 - Found ContextHandle in object of type GetIFDCapabilities. 2018-01-25 09:56:28,843 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:28,844 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:28,844 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.GetIFDCapabilities 2018-01-25 09:56:28,845 [IFD Watcher 0] WARN o.o.ifd.scio.wrapper.ChannelManager:86 - Terminal 'REINER SCT cyberJack RFID standard (0810057893) 00 00' is already connected. 2018-01-25 09:56:28,869 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:28,871 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:28,871 [IFD Watcher 0] DEBUG o.o.ifd.event.IfdEventRunner:223 - Found a card insert event (REINER SCT cyberJack RFID standard (0810057893) 00 00). 2018-01-25 09:56:28,873 [IFD Watcher 0] INFO o.o.ifd.event.IfdEventRunner:224 - Card with ATR=3B8780018031B8738401E019 inserted. 2018-01-25 09:56:28,875 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:361 - Event: CARD_INSERTED 2018-01-25 09:56:28,875 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:369 - ConnectionHandle: iso.std.iso_iec._24727.tech.schema.ConnectionHandleType@25826842 2018-01-25 09:56:28,875 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event CARD_INSERTED into event queue. 2018-01-25 09:56:28,875 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:371 - RecognitionInfo: iso.std.iso_iec._24727.tech.schema.ConnectionHandleType$RecognitionInfo@62fe62f0 2018-01-25 09:56:28,875 [IFD Watcher 0] WARN o.o.ifd.scio.wrapper.ChannelManager:86 - Terminal 'REINER SCT cyberJack RFID standard (0810057893) 00 00' is already connected. 2018-01-25 09:56:28,876 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:373 - IFDName: REINER SCT cyberJack RFID standard (0810057893) 00 00 2018-01-25 09:56:28,887 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:131 - Found ContextHandle in object of type Connect. 2018-01-25 09:56:28,888 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:201 - Detecting initial terminal status. 2018-01-25 09:56:28,888 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:205 - Terminal='REINER SCT cyberJack RFID standard (0810057893) 00 00' cardPresent=true 2018-01-25 09:56:28,895 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:28,901 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:28,902 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Connect 2018-01-25 09:56:28,902 [IFD Watcher 1] WARN o.o.ifd.scio.wrapper.ChannelManager:86 - Terminal 'REINER SCT cyberJack RFID standard (0810057893) 00 00' is already connected. 2018-01-25 09:56:28,913 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:28,914 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:28,915 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type BeginTransaction. 2018-01-25 09:56:28,919 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:28,921 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:28,921 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.BeginTransaction 2018-01-25 09:56:28,931 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:28,933 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:28,934 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 09:56:28,941 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:28,942 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:28,942 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 09:56:28,945 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x00 0x0C 0x02 0x3F 0x00 2018-01-25 09:56:28,983 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 09:56:28,991 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:28,991 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:28,992 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 09:56:28,996 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:28,997 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:28,997 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 09:56:28,998 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x02 0x0C 0x02 0x00 0x03 2018-01-25 09:56:29,003 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x6A 0x82 2018-01-25 09:56:29,012 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:29,013 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:29,014 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 09:56:29,018 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:29,019 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:29,019 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 09:56:29,020 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x00 0x0C 0x02 0x3F 0x00 2018-01-25 09:56:29,027 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 09:56:29,037 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:29,037 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:29,038 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 09:56:29,041 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:29,042 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:29,042 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 09:56:29,043 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x02 0x0C 0x02 0x2F 0x00 2018-01-25 09:56:29,050 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 09:56:29,057 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:29,058 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:29,059 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 09:56:29,063 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:29,064 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:29,064 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 09:56:29,065 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xB2 0x04 0x04 0xFF 2018-01-25 09:56:29,068 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x6D 0x00 2018-01-25 09:56:29,075 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:29,076 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:29,077 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 09:56:29,080 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:29,080 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:29,081 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 09:56:29,082 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x00 0x0C 0x02 0x3F 0x00 2018-01-25 09:56:29,087 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 09:56:29,095 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:29,095 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:29,096 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 09:56:29,100 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:29,101 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:29,101 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 09:56:29,102 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x02 0x0C 0x02 0x2F 0x00 2018-01-25 09:56:29,109 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 09:56:29,115 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:29,117 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:29,118 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 09:56:29,123 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:29,124 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:29,124 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 09:56:29,125 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xB2 0x03 0x04 0xFF 2018-01-25 09:56:29,128 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x6D 0x00 2018-01-25 09:56:29,137 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:29,138 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:29,138 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 09:56:29,141 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:29,142 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:29,143 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 09:56:29,144 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x04 0x0C 0x0F 0xF0 0x45 0x73 0x74 0x45 0x49 0x44 0x20 0x76 0x65 0x72 0x20 0x31 0x2E 0x30 2018-01-25 09:56:29,153 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x6A 0x82 2018-01-25 09:56:29,160 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:29,161 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:29,161 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 09:56:29,164 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:29,165 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:29,165 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 09:56:29,167 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x04 0x0C 0x0F 0xD2 0x33 0x00 0x00 0x00 0x45 0x73 0x74 0x45 0x49 0x44 0x20 0x76 0x33 0x35 2018-01-25 09:56:29,175 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x6A 0x82 2018-01-25 09:56:29,183 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:29,184 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:29,185 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 09:56:29,188 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:29,189 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:29,190 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 09:56:29,191 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x00 0x0C 0x02 0x3F 0x00 2018-01-25 09:56:29,199 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 09:56:29,205 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:29,206 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:29,206 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 09:56:29,209 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:29,210 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:29,210 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 09:56:29,211 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x02 0x0C 0x02 0x2F 0x00 2018-01-25 09:56:29,217 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 09:56:29,224 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:29,225 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:29,225 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 09:56:29,228 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:29,229 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:29,229 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 09:56:29,230 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xB0 0x00 0x00 0xFF 2018-01-25 09:56:29,245 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x61 0x32 0x4F 0x0F 0xE8 0x28 0xBD 0x08 0x0F 0xA0 0x00 0x00 0x01 0x67 0x45 0x53 0x49 0x47 0x4E 0x50 0x0F 0x43 0x49 0x41 0x20 0x7A 0x75 0x20 0x44 0x46 0x2E 0x65 0x53 0x69 0x67 0x6E 0x51 0x00 0x73 0x0C 0x4F 0x0A 0xA0 0x00 0x00 0x01 0x67 0x45 0x53 0x49 0x47 0x4E 0x61 0x09 0x4F 0x07 0xA0 0x00 0x00 0x02 0x47 0x10 0x01 0x61 0x0B 0x4F 0x09 0xE8 0x07 0x04 0x00 0x7F 0x00 0x07 0x03 0x02 0x61 0x0C 0x4F 0x0A 0xA0 0x00 0x00 0x01 0x67 0x45 0x53 0x49 0x47 0x4E 0x62 0x82 2018-01-25 09:56:29,253 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:29,254 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:29,255 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type EndTransaction. 2018-01-25 09:56:29,257 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:29,258 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:29,258 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.EndTransaction 2018-01-25 09:56:29,274 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:29,275 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:29,276 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Disconnect. 2018-01-25 09:56:29,279 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:29,280 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:29,280 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Disconnect 2018-01-25 09:56:29,288 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:29,288 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:29,289 [IFD Watcher 1] DEBUG org.openecard.ifd.event.Recognizer:60 - Found a recognized card event (REINER SCT cyberJack RFID standard (0810057893) 00 00). 2018-01-25 09:56:29,290 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:361 - Event: CARD_RECOGNIZED 2018-01-25 09:56:29,292 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:369 - ConnectionHandle: iso.std.iso_iec._24727.tech.schema.ConnectionHandleType@65603115 2018-01-25 09:56:29,297 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:371 - RecognitionInfo: iso.std.iso_iec._24727.tech.schema.ConnectionHandleType$RecognitionInfo@164aaa65 2018-01-25 09:56:29,297 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:373 - IFDName: REINER SCT cyberJack RFID standard (0810057893) 00 00 2018-01-25 09:56:29,291 [Dispatcher Event 1] INFO o.o.c.sal.state.SALStateCallback:63 - Add ConnectionHandle to SAL: ConnectionHandle: Session: H1NctFpkvY7sCUUpPBSegA ContextHandle: 0C4CFAEE07B92B3DB449BBD1F144DC09 IFDName: REINER SCT cyberJack RFID standard (0810057893) 00 00 SlotIndex: 0 CardType: http://bsi.bund.de/cif/npa.xml 2018-01-25 09:56:29,313 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event CARD_RECOGNIZED into event queue. 2018-01-25 09:56:51,463 [IFD Watcher 0] DEBUG o.o.common.util.HandlerUtils:131 - Found ContextHandle in object of type GetIFDCapabilities. 2018-01-25 09:56:51,468 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 09:56:51,468 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 09:56:51,469 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.GetIFDCapabilities 2018-01-25 09:56:51,472 [IFD Watcher 0] DEBUG org.openecard.ifd.scio.IFD:350 - Failed to request status from terminal. org.openecard.common.ifd.scio.SCIOException: Reader refused to connect card with any protocol. at org.openecard.ifd.scio.wrapper.SingleThreadChannel.connectCard(SingleThreadChannel.java:139) at org.openecard.ifd.scio.wrapper.SingleThreadChannel.(SingleThreadChannel.java:80) at org.openecard.ifd.scio.wrapper.ChannelManager.openMasterChannel(ChannelManager.java:90) at org.openecard.ifd.scio.IFD.getIFDCapabilities(IFD.java:285) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.openecard.transport.dispatcher.Service.invoke(Service.java:192) at org.openecard.transport.dispatcher.MessageDispatcher.deliver(MessageDispatcher.java:116) at org.openecard.transport.dispatcher.MessageDispatcher.safeDeliver(MessageDispatcher.java:135) at org.openecard.ifd.event.IfdEventRunner.getCapabilities(IfdEventRunner.java:279) at org.openecard.ifd.event.IfdEventRunner.fireEvents(IfdEventRunner.java:189) at org.openecard.ifd.event.IfdEventRunner.run(IfdEventRunner.java:128) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 2018-01-25 09:56:51,481 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 09:56:51,482 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 09:56:51,482 [IFD Watcher 0] DEBUG o.o.ifd.event.IfdEventRunner:250 - Found a card removed event (REINER SCT cyberJack RFID standard (0810057893) 00 00). 2018-01-25 09:56:51,483 [Dispatcher Event 2] INFO o.o.c.sal.state.SALStateCallback:73 - Remove ConnectionHandle from SAL. ConnectionHandle: Session: H1NctFpkvY7sCUUpPBSegA ContextHandle: 0C4CFAEE07B92B3DB449BBD1F144DC09 IFDName: REINER SCT cyberJack RFID standard (0810057893) 00 00 SlotIndex: 0 2018-01-25 09:56:51,484 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:361 - Event: CARD_REMOVED 2018-01-25 09:56:51,484 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:369 - ConnectionHandle: iso.std.iso_iec._24727.tech.schema.ConnectionHandleType@2f84bb76 2018-01-25 09:56:51,484 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:371 - RecognitionInfo: null 2018-01-25 09:56:51,485 [Dispatcher Event 3] DEBUG org.openecard.richclient.gui.Status:373 - IFDName: REINER SCT cyberJack RFID standard (0810057893) 00 00 2018-01-25 09:56:51,486 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event CARD_REMOVED into event queue. 2018-01-25 09:56:51,488 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:201 - Detecting initial terminal status. 2018-01-25 09:56:51,489 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:205 - Terminal='REINER SCT cyberJack RFID standard (0810057893) 00 00' cardPresent=false 2018-01-25 09:59:54,847 [Thread-8] DEBUG o.o.c.b.h.h.HttpAppPluginActionHandler:88 - HTTP request: GET /eID-Client?tcTokenURL=https%3A%2F%2Fwww.elster.de%2Feportal%2Fregistrierung-auswahl%2Feid-fwd%2FJA0?ElsterRequestKeys.NPA_REG_ID=f9601f51-99bd-4b25-9f76-ff98768ece05 [Host: 127.0.0.1:24727, Connection: keep-alive, Upgrade-Insecure-Requests: 1, User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Ubuntu Chromium/63.0.3239.84 Chrome/63.0.3239.84 Safari/537.36, Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8, Accept-Encoding: gzip, deflate, br, Accept-Language: de-DE,de;q=0.9,en-US;q=0.8,en;q=0.7] 2018-01-25 09:59:54,863 [Thread-8] WARN org.openecard.common.I18n:152 - Failed to load resource tr03112 for lang de_DE. 2018-01-25 09:59:54,874 [Thread-8] WARN org.openecard.common.I18n:152 - Failed to load resource tctoken for lang de_DE. 2018-01-25 09:59:54,877 [Thread-8] WARN org.openecard.common.I18n:152 - Failed to load resource pinplugin for lang de_DE. 2018-01-25 09:59:54,879 [Thread-8] WARN org.openecard.common.I18n:152 - Failed to load resource pace for lang de_DE. 2018-01-25 09:59:54,996 [Thread-8] WARN org.openecard.common.I18n:152 - Failed to load resource gui for lang de_DE. 2018-01-25 09:59:55,153 [Thread-8] DEBUG org.openecard.gui.swing.StepBar:97 - Selecting index 0, previous was -1. 2018-01-25 09:59:55,400 [Instant-Return-Thread-1] DEBUG o.o.gui.swing.SwingNavigator:244 - Received event: Button.next 2018-01-25 09:59:55,405 [Instant-Return-Thread-1] DEBUG org.openecard.gui.swing.StepFrame:257 - Trying to kill background task if it exists. 2018-01-25 09:59:55,408 [Instant-Return-Thread-1] DEBUG org.openecard.gui.swing.StepFrame:222 - Exchange result for step 'Karte bereitstellen'. 2018-01-25 10:00:07,015 [SCIO Watcher 0] INFO o.o.i.s.wrapper.SingleThreadChannel:144 - Card connected with protocol T=1. 2018-01-25 10:00:07,016 [IFD Watcher 0] DEBUG o.o.common.util.HandlerUtils:131 - Found ContextHandle in object of type GetIFDCapabilities. 2018-01-25 10:00:07,021 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,022 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,023 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.GetIFDCapabilities 2018-01-25 10:00:07,023 [IFD Watcher 0] WARN o.o.ifd.scio.wrapper.ChannelManager:86 - Terminal 'REINER SCT cyberJack RFID standard (0810057893) 00 00' is already connected. 2018-01-25 10:00:07,038 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,040 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,040 [IFD Watcher 0] DEBUG o.o.ifd.event.IfdEventRunner:223 - Found a card insert event (REINER SCT cyberJack RFID standard (0810057893) 00 00). 2018-01-25 10:00:07,041 [IFD Watcher 0] INFO o.o.ifd.event.IfdEventRunner:224 - Card with ATR=3B8780018031B8738401E019 inserted. 2018-01-25 10:00:07,041 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event CARD_INSERTED into event queue. 2018-01-25 10:00:07,041 [IFD Watcher 0] WARN o.o.ifd.scio.wrapper.ChannelManager:86 - Terminal 'REINER SCT cyberJack RFID standard (0810057893) 00 00' is already connected. 2018-01-25 10:00:07,042 [Dispatcher Event 6] DEBUG org.openecard.richclient.gui.Status:361 - Event: CARD_INSERTED 2018-01-25 10:00:07,043 [Dispatcher Event 6] DEBUG org.openecard.richclient.gui.Status:369 - ConnectionHandle: iso.std.iso_iec._24727.tech.schema.ConnectionHandleType@62c7408d 2018-01-25 10:00:07,043 [Dispatcher Event 6] DEBUG org.openecard.richclient.gui.Status:371 - RecognitionInfo: iso.std.iso_iec._24727.tech.schema.ConnectionHandleType$RecognitionInfo@6c00a2a5 2018-01-25 10:00:07,043 [Dispatcher Event 6] DEBUG org.openecard.richclient.gui.Status:373 - IFDName: REINER SCT cyberJack RFID standard (0810057893) 00 00 2018-01-25 10:00:07,046 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:131 - Found ContextHandle in object of type Connect. 2018-01-25 10:00:07,053 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,054 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,055 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Connect 2018-01-25 10:00:07,055 [IFD Watcher 2] WARN o.o.ifd.scio.wrapper.ChannelManager:86 - Terminal 'REINER SCT cyberJack RFID standard (0810057893) 00 00' is already connected. 2018-01-25 10:00:07,057 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:201 - Detecting initial terminal status. 2018-01-25 10:00:07,057 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:205 - Terminal='REINER SCT cyberJack RFID standard (0810057893) 00 00' cardPresent=true 2018-01-25 10:00:07,094 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,101 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,102 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type BeginTransaction. 2018-01-25 10:00:07,105 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,108 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,109 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.BeginTransaction 2018-01-25 10:00:07,125 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,127 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,127 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:07,132 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,133 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,133 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:07,136 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x00 0x0C 0x02 0x3F 0x00 2018-01-25 10:00:07,172 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 10:00:07,179 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,180 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,180 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:07,183 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,183 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,184 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:07,184 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x02 0x0C 0x02 0x00 0x03 2018-01-25 10:00:07,196 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x6A 0x82 2018-01-25 10:00:07,208 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,214 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,215 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:07,220 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,221 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,221 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:07,227 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x00 0x0C 0x02 0x3F 0x00 2018-01-25 10:00:07,235 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 10:00:07,246 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,247 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,247 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:07,252 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,254 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,254 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:07,255 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x02 0x0C 0x02 0x2F 0x00 2018-01-25 10:00:07,262 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 10:00:07,278 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,279 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,279 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:07,284 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,284 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,284 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:07,286 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xB2 0x04 0x04 0xFF 2018-01-25 10:00:07,289 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x6D 0x00 2018-01-25 10:00:07,294 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,295 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,295 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:07,299 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,299 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,300 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:07,301 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x00 0x0C 0x02 0x3F 0x00 2018-01-25 10:00:07,308 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 10:00:07,314 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,315 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,315 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:07,318 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,320 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,320 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:07,321 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x02 0x0C 0x02 0x2F 0x00 2018-01-25 10:00:07,328 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 10:00:07,334 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,337 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,338 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:07,341 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,342 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,343 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:07,343 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xB2 0x03 0x04 0xFF 2018-01-25 10:00:07,347 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x6D 0x00 2018-01-25 10:00:07,353 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,354 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,354 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:07,357 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,358 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,359 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:07,360 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x04 0x0C 0x0F 0xF0 0x45 0x73 0x74 0x45 0x49 0x44 0x20 0x76 0x65 0x72 0x20 0x31 0x2E 0x30 2018-01-25 10:00:07,370 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x6A 0x82 2018-01-25 10:00:07,378 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,380 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,380 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:07,384 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,384 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,384 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:07,385 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x04 0x0C 0x0F 0xD2 0x33 0x00 0x00 0x00 0x45 0x73 0x74 0x45 0x49 0x44 0x20 0x76 0x33 0x35 2018-01-25 10:00:07,396 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x6A 0x82 2018-01-25 10:00:07,409 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,410 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,414 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:07,418 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,418 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,419 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:07,420 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x00 0x0C 0x02 0x3F 0x00 2018-01-25 10:00:07,428 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 10:00:07,435 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,436 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,437 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:07,440 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,441 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,441 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:07,442 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x02 0x0C 0x02 0x2F 0x00 2018-01-25 10:00:07,449 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 10:00:07,458 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,459 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,459 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:07,463 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,464 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,464 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:07,465 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xB0 0x00 0x00 0xFF 2018-01-25 10:00:07,474 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x61 0x32 0x4F 0x0F 0xE8 0x28 0xBD 0x08 0x0F 0xA0 0x00 0x00 0x01 0x67 0x45 0x53 0x49 0x47 0x4E 0x50 0x0F 0x43 0x49 0x41 0x20 0x7A 0x75 0x20 0x44 0x46 0x2E 0x65 0x53 0x69 0x67 0x6E 0x51 0x00 0x73 0x0C 0x4F 0x0A 0xA0 0x00 0x00 0x01 0x67 0x45 0x53 0x49 0x47 0x4E 0x61 0x09 0x4F 0x07 0xA0 0x00 0x00 0x02 0x47 0x10 0x01 0x61 0x0B 0x4F 0x09 0xE8 0x07 0x04 0x00 0x7F 0x00 0x07 0x03 0x02 0x61 0x0C 0x4F 0x0A 0xA0 0x00 0x00 0x01 0x67 0x45 0x53 0x49 0x47 0x4E 0x62 0x82 2018-01-25 10:00:07,483 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,483 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,484 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type EndTransaction. 2018-01-25 10:00:07,486 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,487 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,487 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.EndTransaction 2018-01-25 10:00:07,500 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,500 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,500 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Disconnect. 2018-01-25 10:00:07,504 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:07,505 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:07,505 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Disconnect 2018-01-25 10:00:07,512 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:07,513 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:07,513 [IFD Watcher 2] DEBUG org.openecard.ifd.event.Recognizer:60 - Found a recognized card event (REINER SCT cyberJack RFID standard (0810057893) 00 00). 2018-01-25 10:00:07,514 [Dispatcher Event 5] DEBUG org.openecard.richclient.gui.Status:361 - Event: CARD_RECOGNIZED 2018-01-25 10:00:07,515 [Dispatcher Event 5] DEBUG org.openecard.richclient.gui.Status:369 - ConnectionHandle: iso.std.iso_iec._24727.tech.schema.ConnectionHandleType@64d9bede 2018-01-25 10:00:07,517 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event CARD_RECOGNIZED into event queue. 2018-01-25 10:00:07,515 [Dispatcher Event 8] INFO o.o.c.sal.state.SALStateCallback:63 - Add ConnectionHandle to SAL: ConnectionHandle: Session: H1NctFpkvY7sCUUpPBSegA ContextHandle: 0C4CFAEE07B92B3DB449BBD1F144DC09 IFDName: REINER SCT cyberJack RFID standard (0810057893) 00 00 SlotIndex: 0 CardType: http://bsi.bund.de/cif/npa.xml 2018-01-25 10:00:07,516 [Dispatcher Event 5] DEBUG org.openecard.richclient.gui.Status:371 - RecognitionInfo: iso.std.iso_iec._24727.tech.schema.ConnectionHandleType$RecognitionInfo@6a1e5c35 2018-01-25 10:00:07,523 [Dispatcher Event 5] DEBUG org.openecard.richclient.gui.Status:373 - IFDName: REINER SCT cyberJack RFID standard (0810057893) 00 00 2018-01-25 10:00:07,591 [Thread-8] INFO o.o.binding.tctoken.ResourceContext:207 - Trying to load resource from: https://www.elster.de/eportal/registrierung-auswahl/eid-fwd/JA0?ElsterRequestKeys.NPA_REG_ID=f9601f51-99bd-4b25-9f76-ff98768ece05 2018-01-25 10:00:07,695 [Thread-8] INFO o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for java. Trying next one. 2018-01-25 10:00:07,732 [Thread-8] DEBUG o.o.c.t.proxy.ProxySettingsLoader$1:80 - Firefox settings folder is {0} 2018-01-25 10:00:07,745 [Thread-8] WARN o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found. 2018-01-25 10:00:07,745 [Thread-8] WARN o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found. 2018-01-25 10:00:07,746 [Thread-8] INFO o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for firefox. Trying next one. 2018-01-25 10:00:07,746 [Thread-8] WARN o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found. 2018-01-25 10:00:07,747 [Thread-8] WARN o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found. 2018-01-25 10:00:07,747 [Thread-8] INFO o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for desktop. Trying next one. 2018-01-25 10:00:07,749 [Thread-8] INFO o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for env. Trying next one. 2018-01-25 10:00:07,754 [Thread-8] INFO o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for java. Trying next one. 2018-01-25 10:00:07,762 [Thread-8] DEBUG o.o.c.t.proxy.ProxySettingsLoader$1:80 - Firefox settings folder is {0} 2018-01-25 10:00:07,764 [Thread-8] WARN o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found. 2018-01-25 10:00:07,765 [Thread-8] WARN o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found. 2018-01-25 10:00:07,765 [Thread-8] INFO o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for firefox. Trying next one. 2018-01-25 10:00:07,781 [Thread-8] WARN o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found. 2018-01-25 10:00:07,783 [Thread-8] WARN o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found. 2018-01-25 10:00:07,784 [Thread-8] INFO o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for desktop. Trying next one. 2018-01-25 10:00:07,785 [Thread-8] INFO o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for env. Trying next one. 2018-01-25 10:00:07,789 [Thread-8] DEBUG o.o.crypto.tls.proxy.ProxySettings:133 - Selecting proxy: DIRECT 2018-01-25 10:00:07,877 [Thread-8] DEBUG o.o.binding.tctoken.ResourceContext:244 - Performing TLS handshake. 2018-01-25 10:00:08,161 [Thread-8] DEBUG o.o.c.tls.verify.HostnameVerifier:126 - Comparing connection hostname against certificate hostname: [www.elster.de] [www.elster.de] 2018-01-25 10:00:08,478 [Thread-8] DEBUG o.o.binding.tctoken.ResourceContext:246 - TLS handshake performed. 2018-01-25 10:00:08,487 [Thread-8] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request: GET /eportal/registrierung-auswahl/eid-fwd/JA0?ElsterRequestKeys.NPA_REG_ID=f9601f51-99bd-4b25-9f76-ff98768ece05 HTTP/1.1 Connection: keep-alive User-Agent: Open eCard App/org.openecard.common.SemanticVersion@e580929 Host: www.elster.de Accept: text/xml, */*;q=0.8 Accept-Charset: utf-8, *;q=0.8 2018-01-25 10:00:08,487 [Thread-8] DEBUG o.o.binding.tctoken.ResourceContext:267 - Sending HTTP request. 2018-01-25 10:00:08,694 [Thread-8] DEBUG o.o.t.h.cookies.CookieManager:130 - Setting cookie JSESSIONID=0DAA40230D806D42BD4DF62E4BC216EB for domain www.elster.de. 2018-01-25 10:00:08,694 [Thread-8] DEBUG o.o.binding.tctoken.ResourceContext:270 - HTTP response received. 2018-01-25 10:00:08,695 [Thread-8] DEBUG o.o.transport.httpcore.HttpUtils:112 - HTTP Response: HTTP/1.1 303 See Other X-Content-Type-Options: nosniff X-XSS-Protection: 1; mode=block Cache-Control: no-cache, no-store, max-age=0, must-revalidate Pragma: no-cache Expires: 0 Strict-Transport-Security: max-age=31536000 X-Frame-Options: SAMEORIGIN Content-Security-Policy: default-src 'self' ; style-src 'self' ; media-src 'self' https://www.elster.de ; img-src 'self' https://www.elster.de ; form-action 'self' ; object-src 'self' blob: ; frame-src 'self' X-Content-Security-Policy: default-src 'self' ; style-src 'self' ; media-src 'self' https://www.elster.de ; img-src 'self' https://www.elster.de ; form-action 'self' ; object-src 'self' blob: ; frame-src 'self' X-WebKit-CSP: default-src 'self' ; style-src 'self' ; media-src 'self' https://www.elster.de ; img-src 'self' https://www.elster.de ; form-action 'self' ; object-src 'self' blob: ; frame-src 'self' X-UA-Compatible: IE=edge Location: https://eid.elsteronline.de/gov_autent/async?SAMLRequest=rVVhb9owEP0rkb8nDmnpmEWo0qZMTN2GKJ2mfZlMcgVrxs5sB9p%2Fv3OS0mwam8b2CeTj3t29d%2FcYXz5uZbADY4VWKRlEMQlAFboUap2S%2B%2BU0HJHLydjyrUwqltVuoxbwrQbrAkxUlrWRlNRGMc2tsEzxLVjmCnaXvbtlSRSzyminCy1JkFkLxmGpa61svQVzB2YnCrhf3KZk41xlGaX7%2FT4CaR2YqAQKlTaOS2pgLawzAkyt1iGv7Z5vJPWfICyvqtCAwybo2wxHyLFBobiv9IILouxwtZJCgUdf690XXjtQjnL7pAoSzPKU5DE7j1l2zq4zNjxjgxs2vGLTKUsGLBmy61dslLCzKZvesAsMZZhkbQ0zZR1XLiVJPBiF8SBMhsv4NYtjFo%2Bi4cX5ZxLMjd6JEsx75Cgl7ZAhzBHh47MESBjpCGcNrOkz%2FXui%2BTO9ZPKCPaaNRh3YQcubR5zaq24nY2TmB20Psa40xlsaUZ2VFdGqVmWjzSyn5JT2upxHKw64XvX9WaTNmiZxPKCf3t3eFRvY8lA0vBbQJwkp8k13uwhl5nA1VigkTtOOe3gJWrJz7uDDw5UwboMr3uUK00tNiTM1EHoMYYFLZUThoJzlJ0K8ETtQvh97IkCuCzwb5ZZPFfJx0hhTvhXy6V%2BamEteIJfIB%2B5yI8wfGqFHtWoifVs5rN5knJWl8BfM5Zwb5AxvxbaL017BSttwZQDpaK3GtMaEq3H4feDNKCVoD1IUjR0sDVeWF%2F7rTD1oEjhu1oBHW0iBvJJgx2Xt1%2BUvLQC35ueqR0uhB6Lj%2Fs9Sxwf0Oh8dctH3VPtVK2e0lHu0aH8F9FcC4HP3Z9A3kOe3vpKT7w%3D%3D&RelayState=1516870808568&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%2Frsa-sha256&Signature=KLCBYBPXI8YO7%2Fn9s5Rjc2a7X8Jy9PT6tIKK1AKFAOowh8OhAjxcJuSez2O7G1E2ZYvan2bExJZ4%0ArjAbDbtJx98ANSK9VB93O4K5gqNE5Hlaiy00QoQrE4zUTlLDq5c2r0I23AkhqwQ%2FQEnV2WOuF5oG%0A%2FGVDlOtlw7IwcvIDGx5EAFKv9H3xyu%2B%2B2IvgiyHq0Jl7OAbfRIL578cbP9chyF7Js0nhWhlSfzrj%0ACgqNcTz4u87ptirHkjIuoy2ftL%2BhRolvcJ%2FmZkvMonCJnWRATZF2h5ptj63IYJHn47XGYbNJLQhp%0Aeoct2VmyycJKYf3QcoYJZI3mAeM3ISS9gA4ppQ%3D%3D Content-Length: 0 Date: Thu, 25 Jan 2018 09:00:08 GMT Set-Cookie: JSESSIONID=0DAA40230D806D42BD4DF62E4BC216EB; Path=/eportal/; Secure; HttpOnly 2018-01-25 10:00:08,697 [Thread-8] INFO o.o.c.t.ClientCertDefaultTlsClient:321 - TLS warning sent. 2018-01-25 10:00:08,697 [Thread-8] INFO o.o.c.t.ClientCertDefaultTlsClient:323 - TLS(WARN): Close [close_notify=0] --> Connection closed 2018-01-25 10:00:08,698 [Thread-8] INFO o.o.binding.tctoken.ResourceContext:207 - Trying to load resource from: https://eid.elsteronline.de/gov_autent/async?SAMLRequest=rVVhb9owEP0rkb8nDmnpmEWo0qZMTN2GKJ2mfZlMcgVrxs5sB9p%2Fv3OS0mwam8b2CeTj3t29d%2FcYXz5uZbADY4VWKRlEMQlAFboUap2S%2B%2BU0HJHLydjyrUwqltVuoxbwrQbrAkxUlrWRlNRGMc2tsEzxLVjmCnaXvbtlSRSzyminCy1JkFkLxmGpa61svQVzB2YnCrhf3KZk41xlGaX7%2FT4CaR2YqAQKlTaOS2pgLawzAkyt1iGv7Z5vJPWfICyvqtCAwybo2wxHyLFBobiv9IILouxwtZJCgUdf690XXjtQjnL7pAoSzPKU5DE7j1l2zq4zNjxjgxs2vGLTKUsGLBmy61dslLCzKZvesAsMZZhkbQ0zZR1XLiVJPBiF8SBMhsv4NYtjFo%2Bi4cX5ZxLMjd6JEsx75Cgl7ZAhzBHh47MESBjpCGcNrOkz%2FXui%2BTO9ZPKCPaaNRh3YQcubR5zaq24nY2TmB20Psa40xlsaUZ2VFdGqVmWjzSyn5JT2upxHKw64XvX9WaTNmiZxPKCf3t3eFRvY8lA0vBbQJwkp8k13uwhl5nA1VigkTtOOe3gJWrJz7uDDw5UwboMr3uUK00tNiTM1EHoMYYFLZUThoJzlJ0K8ETtQvh97IkCuCzwb5ZZPFfJx0hhTvhXy6V%2BamEteIJfIB%2B5yI8wfGqFHtWoifVs5rN5knJWl8BfM5Zwb5AxvxbaL017BSttwZQDpaK3GtMaEq3H4feDNKCVoD1IUjR0sDVeWF%2F7rTD1oEjhu1oBHW0iBvJJgx2Xt1%2BUvLQC35ueqR0uhB6Lj%2Fs9Sxwf0Oh8dctH3VPtVK2e0lHu0aH8F9FcC4HP3Z9A3kOe3vpKT7w%3D%3D&RelayState=1516870808568&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%2Frsa-sha256&Signature=KLCBYBPXI8YO7%2Fn9s5Rjc2a7X8Jy9PT6tIKK1AKFAOowh8OhAjxcJuSez2O7G1E2ZYvan2bExJZ4%0ArjAbDbtJx98ANSK9VB93O4K5gqNE5Hlaiy00QoQrE4zUTlLDq5c2r0I23AkhqwQ%2FQEnV2WOuF5oG%0A%2FGVDlOtlw7IwcvIDGx5EAFKv9H3xyu%2B%2B2IvgiyHq0Jl7OAbfRIL578cbP9chyF7Js0nhWhlSfzrj%0ACgqNcTz4u87ptirHkjIuoy2ftL%2BhRolvcJ%2FmZkvMonCJnWRATZF2h5ptj63IYJHn47XGYbNJLQhp%0Aeoct2VmyycJKYf3QcoYJZI3mAeM3ISS9gA4ppQ%3D%3D 2018-01-25 10:00:08,699 [Thread-8] DEBUG o.o.crypto.tls.proxy.ProxySettings:133 - Selecting proxy: DIRECT 2018-01-25 10:00:08,776 [Thread-8] DEBUG o.o.binding.tctoken.ResourceContext:244 - Performing TLS handshake. 2018-01-25 10:00:08,919 [Thread-8] DEBUG o.o.c.tls.verify.HostnameVerifier:126 - Comparing connection hostname against certificate hostname: [eid.elsteronline.de] [eid.elsteronline.de] 2018-01-25 10:00:09,005 [Thread-8] DEBUG o.o.binding.tctoken.ResourceContext:246 - TLS handshake performed. 2018-01-25 10:00:09,005 [Thread-8] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request: GET /gov_autent/async?SAMLRequest=rVVhb9owEP0rkb8nDmnpmEWo0qZMTN2GKJ2mfZlMcgVrxs5sB9p%2Fv3OS0mwam8b2CeTj3t29d%2FcYXz5uZbADY4VWKRlEMQlAFboUap2S%2B%2BU0HJHLydjyrUwqltVuoxbwrQbrAkxUlrWRlNRGMc2tsEzxLVjmCnaXvbtlSRSzyminCy1JkFkLxmGpa61svQVzB2YnCrhf3KZk41xlGaX7%2FT4CaR2YqAQKlTaOS2pgLawzAkyt1iGv7Z5vJPWfICyvqtCAwybo2wxHyLFBobiv9IILouxwtZJCgUdf690XXjtQjnL7pAoSzPKU5DE7j1l2zq4zNjxjgxs2vGLTKUsGLBmy61dslLCzKZvesAsMZZhkbQ0zZR1XLiVJPBiF8SBMhsv4NYtjFo%2Bi4cX5ZxLMjd6JEsx75Cgl7ZAhzBHh47MESBjpCGcNrOkz%2FXui%2BTO9ZPKCPaaNRh3YQcubR5zaq24nY2TmB20Psa40xlsaUZ2VFdGqVmWjzSyn5JT2upxHKw64XvX9WaTNmiZxPKCf3t3eFRvY8lA0vBbQJwkp8k13uwhl5nA1VigkTtOOe3gJWrJz7uDDw5UwboMr3uUK00tNiTM1EHoMYYFLZUThoJzlJ0K8ETtQvh97IkCuCzwb5ZZPFfJx0hhTvhXy6V%2BamEteIJfIB%2B5yI8wfGqFHtWoifVs5rN5knJWl8BfM5Zwb5AxvxbaL017BSttwZQDpaK3GtMaEq3H4feDNKCVoD1IUjR0sDVeWF%2F7rTD1oEjhu1oBHW0iBvJJgx2Xt1%2BUvLQC35ueqR0uhB6Lj%2Fs9Sxwf0Oh8dctH3VPtVK2e0lHu0aH8F9FcC4HP3Z9A3kOe3vpKT7w%3D%3D&RelayState=1516870808568&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%2Frsa-sha256&Signature=KLCBYBPXI8YO7%2Fn9s5Rjc2a7X8Jy9PT6tIKK1AKFAOowh8OhAjxcJuSez2O7G1E2ZYvan2bExJZ4%0ArjAbDbtJx98ANSK9VB93O4K5gqNE5Hlaiy00QoQrE4zUTlLDq5c2r0I23AkhqwQ%2FQEnV2WOuF5oG%0A%2FGVDlOtlw7IwcvIDGx5EAFKv9H3xyu%2B%2B2IvgiyHq0Jl7OAbfRIL578cbP9chyF7Js0nhWhlSfzrj%0ACgqNcTz4u87ptirHkjIuoy2ftL%2BhRolvcJ%2FmZkvMonCJnWRATZF2h5ptj63IYJHn47XGYbNJLQhp%0Aeoct2VmyycJKYf3QcoYJZI3mAeM3ISS9gA4ppQ%3D%3D HTTP/1.1 Connection: keep-alive User-Agent: Open eCard App/org.openecard.common.SemanticVersion@e580929 Host: eid.elsteronline.de Accept: text/xml, */*;q=0.8 Accept-Charset: utf-8, *;q=0.8 2018-01-25 10:00:09,006 [Thread-8] DEBUG o.o.binding.tctoken.ResourceContext:267 - Sending HTTP request. 2018-01-25 10:00:09,115 [Thread-8] DEBUG o.o.binding.tctoken.ResourceContext:270 - HTTP response received. 2018-01-25 10:00:09,116 [Thread-8] DEBUG o.o.transport.httpcore.HttpUtils:112 - HTTP Response: HTTP/1.1 302 Moved Temporarily Server: Apache-Coyote/1.1 Content-Security-Policy: default-src 'self' Cache-Control: no-cache, no-store Pragma: no-cache Location: https://eid.elsteronline.de/ecardpaos/startauthentication?DateOfBirth=true&applicationTransactionInfo=D0%3A40%3AA4%3ACA%3A53%3A1E%3A5B%3AFF%3A21%3A25%3AC7%3A82%3A3F%3AFE%3A6E%3A5A&RestrictedID=true&DocumentType=true&FamilyNames=true&applicationTransactionInfoName=Registrierungskontrollwert&receiverUrl=https%3A%2F%2Feidpaos.elsteronline.de%2Fecardpaos%2Fpaosreceiver&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%23rsa-sha256&requestID=d9904910-9752-4365-8ad0-0140eea2b460&GivenNames=true&Signature=gPJow0msFjVB%2FiXRbglYh5BgsID5zjmQT7Iu%2BzsbZGChrwU3InZh8%2BelgVoqtzshcum5PPVgfnvU5hWTbNYUG%2F7lbpgh64jjihBYedmT5puwn3hppcbMKorNe4pFcJxU8LHs%2FgPF1w07o%2B2PoD1%2B33i6M3TYwavJ0ZchkdTC5Ux5a6iTRGQL3IKWU8UXn9qUWltmSGYge8fEUr2z%2B4NjKzCfWhvr567UV7rBtbEf5f80CGTIKfsZ2j86dHY9uUC%2FMvDjZ4cjjHvhjUTj%2BMmfxCrsL%2FagNNLBz9HENReI%2BgcAhGFF2L0dmY6R39seU75s0KpQ1vOPuTCxrR7wrIM%2BLw%3D%3D&PlaceOfResidence=true&idProviderUrl=https%3A%2F%2Feid.elsteronline.de%2Fgov_autent%2Fasync%3FrefID%3D_5c41d2ba455507270ee7ef6fb1f128a05e4592fe Content-Length: 0 Date: Thu, 25 Jan 2018 09:00:09 GMT 2018-01-25 10:00:09,116 [Thread-8] INFO o.o.c.t.ClientCertDefaultTlsClient:321 - TLS warning sent. 2018-01-25 10:00:09,117 [Thread-8] INFO o.o.c.t.ClientCertDefaultTlsClient:323 - TLS(WARN): Close [close_notify=0] --> Connection closed 2018-01-25 10:00:09,118 [Thread-8] INFO o.o.binding.tctoken.ResourceContext:207 - Trying to load resource from: https://eid.elsteronline.de/ecardpaos/startauthentication?DateOfBirth=true&applicationTransactionInfo=D0%3A40%3AA4%3ACA%3A53%3A1E%3A5B%3AFF%3A21%3A25%3AC7%3A82%3A3F%3AFE%3A6E%3A5A&RestrictedID=true&DocumentType=true&FamilyNames=true&applicationTransactionInfoName=Registrierungskontrollwert&receiverUrl=https%3A%2F%2Feidpaos.elsteronline.de%2Fecardpaos%2Fpaosreceiver&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%23rsa-sha256&requestID=d9904910-9752-4365-8ad0-0140eea2b460&GivenNames=true&Signature=gPJow0msFjVB%2FiXRbglYh5BgsID5zjmQT7Iu%2BzsbZGChrwU3InZh8%2BelgVoqtzshcum5PPVgfnvU5hWTbNYUG%2F7lbpgh64jjihBYedmT5puwn3hppcbMKorNe4pFcJxU8LHs%2FgPF1w07o%2B2PoD1%2B33i6M3TYwavJ0ZchkdTC5Ux5a6iTRGQL3IKWU8UXn9qUWltmSGYge8fEUr2z%2B4NjKzCfWhvr567UV7rBtbEf5f80CGTIKfsZ2j86dHY9uUC%2FMvDjZ4cjjHvhjUTj%2BMmfxCrsL%2FagNNLBz9HENReI%2BgcAhGFF2L0dmY6R39seU75s0KpQ1vOPuTCxrR7wrIM%2BLw%3D%3D&PlaceOfResidence=true&idProviderUrl=https%3A%2F%2Feid.elsteronline.de%2Fgov_autent%2Fasync%3FrefID%3D_5c41d2ba455507270ee7ef6fb1f128a05e4592fe 2018-01-25 10:00:09,118 [Thread-8] DEBUG o.o.crypto.tls.proxy.ProxySettings:133 - Selecting proxy: DIRECT 2018-01-25 10:00:09,152 [Thread-8] DEBUG o.o.binding.tctoken.ResourceContext:244 - Performing TLS handshake. 2018-01-25 10:00:09,289 [Thread-8] DEBUG o.o.c.tls.verify.HostnameVerifier:126 - Comparing connection hostname against certificate hostname: [eid.elsteronline.de] [eid.elsteronline.de] 2018-01-25 10:00:09,370 [Thread-8] DEBUG o.o.binding.tctoken.ResourceContext:246 - TLS handshake performed. 2018-01-25 10:00:09,371 [Thread-8] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request: GET /ecardpaos/startauthentication?DateOfBirth=true&applicationTransactionInfo=D0%3A40%3AA4%3ACA%3A53%3A1E%3A5B%3AFF%3A21%3A25%3AC7%3A82%3A3F%3AFE%3A6E%3A5A&RestrictedID=true&DocumentType=true&FamilyNames=true&applicationTransactionInfoName=Registrierungskontrollwert&receiverUrl=https%3A%2F%2Feidpaos.elsteronline.de%2Fecardpaos%2Fpaosreceiver&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%23rsa-sha256&requestID=d9904910-9752-4365-8ad0-0140eea2b460&GivenNames=true&Signature=gPJow0msFjVB%2FiXRbglYh5BgsID5zjmQT7Iu%2BzsbZGChrwU3InZh8%2BelgVoqtzshcum5PPVgfnvU5hWTbNYUG%2F7lbpgh64jjihBYedmT5puwn3hppcbMKorNe4pFcJxU8LHs%2FgPF1w07o%2B2PoD1%2B33i6M3TYwavJ0ZchkdTC5Ux5a6iTRGQL3IKWU8UXn9qUWltmSGYge8fEUr2z%2B4NjKzCfWhvr567UV7rBtbEf5f80CGTIKfsZ2j86dHY9uUC%2FMvDjZ4cjjHvhjUTj%2BMmfxCrsL%2FagNNLBz9HENReI%2BgcAhGFF2L0dmY6R39seU75s0KpQ1vOPuTCxrR7wrIM%2BLw%3D%3D&PlaceOfResidence=true&idProviderUrl=https%3A%2F%2Feid.elsteronline.de%2Fgov_autent%2Fasync%3FrefID%3D_5c41d2ba455507270ee7ef6fb1f128a05e4592fe HTTP/1.1 Connection: keep-alive User-Agent: Open eCard App/org.openecard.common.SemanticVersion@e580929 Host: eid.elsteronline.de Accept: text/xml, */*;q=0.8 Accept-Charset: utf-8, *;q=0.8 2018-01-25 10:00:09,372 [Thread-8] DEBUG o.o.binding.tctoken.ResourceContext:267 - Sending HTTP request. 2018-01-25 10:00:09,449 [Thread-8] DEBUG o.o.binding.tctoken.ResourceContext:270 - HTTP response received. 2018-01-25 10:00:09,451 [Thread-8] DEBUG o.o.transport.httpcore.HttpUtils:112 - HTTP Response: HTTP/1.1 200 OK Server: Apache-Coyote/1.1 Content-Security-Policy: default-src 'self' Content-Type: text/xml;charset=utf-8 Content-Length: 648 Date: Thu, 25 Jan 2018 09:00:09 GMT 2018-01-25 10:00:09,454 [Thread-8] DEBUG o.o.binding.tctoken.TCTokenContext:91 - Cleaned up TCToken: https://eidpaos.elsteronline.de/ecardpaos/paosreceiver d9904910-9752-4365-8ad0-0140eea2b460 https://eid.elsteronline.de/gov_autent/async?refID=_5c41d2ba455507270ee7ef6fb1f128a05e4592fe urn:liberty:paos:2006-08 urn:ietf:rfc:4279 1e3e2bb51a097a8667072d6d795b62d7484b26f837ff5a53d17a0e0fee97cbcdf3b24b044d045209a86c8073e1889f4a8f187c5a6531e32190c5d4fd2979d6e4 2018-01-25 10:00:09,485 [Thread-8] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:09,486 [Thread-8] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:09,487 [Thread-8] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.CardApplicationPath 2018-01-25 10:00:09,498 [Thread-8] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:09,499 [Thread-8] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:09,502 [Thread-8] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:09,503 [Thread-8] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:09,504 [Thread-8] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.CardApplicationConnect 2018-01-25 10:00:09,505 [Thread-8] DEBUG o.o.common.util.HandlerUtils:131 - Found ContextHandle in object of type Connect. 2018-01-25 10:00:09,509 [Thread-8] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:09,518 [Thread-8] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:09,518 [Thread-8] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Connect 2018-01-25 10:00:09,519 [Thread-8] WARN o.o.ifd.scio.wrapper.ChannelManager:86 - Terminal 'REINER SCT cyberJack RFID standard (0810057893) 00 00' is already connected. 2018-01-25 10:00:09,534 [Thread-8] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:09,535 [Thread-8] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:09,539 [Thread-8] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:09,551 [Thread-8] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:09,553 [Thread-8] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:09,553 [Thread-8] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:09,554 [Thread-8] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0xA4 0x00 0x0C 0x02 0x3F 0x00 2018-01-25 10:00:09,564 [Thread-8] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 10:00:09,571 [Thread-8] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:09,573 [Thread-8] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:09,582 [Thread-8] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:09,585 [Thread-8] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:09,599 [PAOS] INFO o.o.c.t.ClientCertDefaultTlsClient:321 - TLS warning sent. 2018-01-25 10:00:09,599 [PAOS] INFO o.o.c.t.ClientCertDefaultTlsClient:323 - TLS(WARN): Close [close_notify=0] --> Connection closed 2018-01-25 10:00:09,648 [PAOS] DEBUG org.openecard.transport.paos.PAOS:399 - Opening connection to PAOS server. 2018-01-25 10:00:09,650 [PAOS] DEBUG o.o.crypto.tls.proxy.ProxySettings:133 - Selecting proxy: DIRECT 2018-01-25 10:00:09,785 [PAOS] DEBUG o.o.c.tls.verify.HostnameVerifier:126 - Comparing connection hostname against certificate hostname: [eidpaos.elsteronline.de] [eidpaos.elsteronline.de] 2018-01-25 10:00:09,924 [PAOS] DEBUG org.openecard.transport.paos.PAOS:402 - Connection to PAOS server established. 2018-01-25 10:00:09,929 [PAOS] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request (before adding content): POST /ecardpaos/paosreceiver HTTP/1.1 Connection: keep-alive User-Agent: Open eCard App/org.openecard.common.SemanticVersion@e580929 Host: eidpaos.elsteronline.de PAOS: ver="urn:liberty:paos:2006-08" ;"urn:iso:std:iso-iec:24727:tech:schema:Transmit";"http://www.bsi.bund.de/ecard/api/1.0#InitializeFramework";"urn:iso:std:iso-iec:24727:tech:schema:StartSession";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationEndSession";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationList";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationServiceList";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationServiceDescribe";"urn:iso:std:iso-iec:24727:tech:schema:DataSetList";"urn:iso:std:iso-iec:24727:tech:schema:DataSetSelect";"urn:iso:std:iso-iec:24727:tech:schema:DSIList";"urn:iso:std:iso-iec:24727:tech:schema:DSIWrite";"urn:iso:std:iso-iec:24727:tech:schema:DSIRead";"urn:iso:std:iso-iec:24727:tech:schema:Encipher";"urn:iso:std:iso-iec:24727:tech:schema:Decipher";"urn:iso:std:iso-iec:24727:tech:schema:GetRandom";"urn:iso:std:iso-iec:24727:tech:schema:Sign";"urn:iso:std:iso-iec:24727:tech:schema:VerifySignature";"urn:iso:std:iso-iec:24727:tech:schema:VerifyCertificate";"urn:iso:std:iso-iec:24727:tech:schema:DIDList";"urn:iso:std:iso-iec:24727:tech:schema:DIDGet";"urn:iso:std:iso-iec:24727:tech:schema:DIDAuthenticate";"urn:iso:std:iso-iec:24727:tech:schema:ACLList";"urn:iso:std:iso-iec:24727:tech:schema:Hash" Accept: text/xml, application/xml, application/vnd.paos+xml 2018-01-25 10:00:10,006 [PAOS] DEBUG org.openecard.transport.paos.PAOS:234 - Message sent:
urn:liberty:paos:2006-08
http://www.projectliberty.org/2006/01/role/paos
http://www.bsi.bund.de/ecard/api/1.1/PAOS/GetNextCommand
http://www.projectliberty.org/2006/02/role/paos
 urn:uuid:bf7a0269-c9b4-4da8-8fc5-816b9624669a
d9904910-9752-4365-8ad0-0140eea2b460 H1NctFpkvY7sCUUpPBSegA 0C4CFAEE07B92B3DB449BBD1F144DC09 REINER SCT cyberJack RFID standard (0810057893) 00 00 0 3F00 874B4EF35DD1A3A87611A06D91439BA8E983AE516CDE2ABE http://bsi.bund.de/cif/npa.xml Open eCard App 1 3 0 1 1 4 urn:oid:1.3.162.15480.3.0.14 urn:oid:1.3.162.15480.3.0.14.2 urn:oid:1.3.162.15480.3.0.25 urn:oid:1.3.162.15480.3.0.9 2018-01-25 10:00:10,007 [PAOS] DEBUG org.openecard.transport.paos.PAOS:318 - Sending HTTP request. 2018-01-25 10:00:10,325 [PAOS] DEBUG org.openecard.transport.paos.PAOS:320 - HTTP response received. 2018-01-25 10:00:10,325 [PAOS] WARN org.openecard.transport.paos.PAOS:424 - The PAOS endpoint sent the http status code 200 which does not conform to the PAOS specification. (See section 9.4 Processing Rules of the PAOS Specification) 2018-01-25 10:00:10,326 [PAOS] DEBUG o.o.transport.httpcore.HttpUtils:112 - HTTP Response: HTTP/1.1 200 OK Server: Apache-Coyote/1.1 Content-Security-Policy: default-src 'self' Content-Type: application/vnd.paos+xml Content-Length: 7189 Date: Thu, 25 Jan 2018 09:00:10 GMT urn:uuid:bf7a0269-c9b4-4da8-8fc5-816b9624669a urn:uuid:24072141-9029-4b8b-b89f-a5ef9da7c393 H1NctFpkvY7sCUUpPBSegA 0C4CFAEE07B92B3DB449BBD1F144DC09 REINER SCT cyberJack RFID standard (0810057893) 00 00 0 3F00 874B4EF35DD1A3A87611A06D91439BA8E983AE516CDE2ABE http://bsi.bund.de/cif/npa.xml PIN 7f218201487f4e8201005f2901004210444544566549444454523130313433317f494f060a04007f000702020202038641048650ffb363aca465ceddff921455e7d8b40b46668f44ef3f6129d1e654e99a2c6caba42ea553b9bcc3143794b8b5be76535d1493ffe93f8d69b0824eaa44b94c5f200e44453030303035313030303035337f4c12060904007f0007030102025305000101db045f25060108000102055f2406010800010206655e732d060904007f00070301030280202f7f530240110ee0adfcaba5bce97e9a44bab167b5677e42b002192a9d238945732d060904007f0007030103018020cde462c123ef567854d77ed12df1183bbcecae8279b4abd5020016b4fe22fa535f374053a0b7cbec3bcc4a95565963137d4e188588d27b81bcb063ffbf8532b600066c97f92d8db68d6cbed4a6091533fc7a54d796c0876405bec2d88bc21fa430289b 7f218201b67f4e82016e5f290100420e44454356434165494430303130327f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a78641048925419fc7f194922cfc6b8dd25ae6a19c1b59216e6cf06270e5d75cfd64205f55cf867bbfefeefd6e680e1fd197f18ab684484901362568efc9adb5c6018d728701015f200e44454356434165494430303130337f4c12060904007f0007030102025305fc0f13ffff5f25060102010200035f24060105010200035f37404d6f08a86a4f18409f6685387dd3c6a7ff5d68ea4f7714a861bbb3bb721d05d3014adf1763c9292f715d8e94ee9b3e1b73ab1382414ebf39dfb3b0fb6c09dbeb 7f218201b67f4e82016e5f290100420e44454356434165494430303130337f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a7864104241d8627338b64f20077ffd558909a096c635ddb222852038eaae642e869a40173d588f817d95db2a6a0f077ea5ee63596a20f85bc3cb176d2f98d88d90219aa8701015f200e44454356434165494430303130347f4c12060904007f0007030102025305fc0f13ffff5f25060105000901045f24060108000901045f3740313a81ed8734e7a8c45f16b55fb603e63027b7f44c2de3a8e782552d35949db221ca33bd41a01da6a1288c7885714fc3a03fa45683b75d3884930ec6738af8a0 7f2181e77f4e81a05f290100420e44454356434165494430303130347f494f060a04007f000702020202038641048b9fbbfa2e30567e97c28f2fcfbfd0b02a129fa27654252a17af90f06d5a1edd6cd9b027145c4154148509d5bae005268d2082f8f6a1e358bdd4be98ea08439a5f2010444544566549444454523130313433317f4c12060904007f0007030102025305400513ff875f25060107010200085f24060108000300085f37403a8a1f9c4ba64edd5093953ab7a1b6a0180a689debdf22f3bad64e776b4647675bc34251fa9ff848cdb3e3ff51da73b7ded2bc70e3ef1f7520c1d41000255fd6 308202fa060a04007f00070301030101a10e0c0c442d547275737420476d6248a2181316687474703a2f2f7777772e642d74727573742e6e6574a3470c45454c53544552202d204672656973746161742042617965726e2c2076657274722e2064757263682042617953744d462c2076657274722e206475726368204261794c665374a417131568747470733a2f2f7777772e656c737465722e6465a58201f40c8201f04e616d652c20416e7363687269667420756e6420452d4d61696c2d4164726573736520646573200d0a4469656e737465616e626965746572733a0d0a454c53544552202d204672656973746161742042617965726e2c0d0a76657274722e2064757263682042617953744d462c0d0a76657274722e206475726368204261794c6653740d0a4b6174686172696e612d766f6e2d426f72612d53747261c39f6520360d0a3830333333204dc3bc6e6368656e0d0a686f746c696e6540656c737465722e64650d0a0d0a4765736368c3a46674737a7765636b3a0d0a0d0a48696e7765697320617566206469652066c3bc722064656e204469656e737465616e626965746572200d0a7a757374c3a46e646967656e205374656c6c656e2c20646965206469652045696e68616c74756e67200d0a64657220566f7273636872696674656e207a756d20446174656e73636875747a200d0a6b6f6e74726f6c6c696572656e3a0d0a4465722042617965726973636865204c616e64657362656175667472616774652066c3bc722064656e20446174656e73636875747a0d0a5761676dc3bc6c6c657273747261c39f652031380d0a3830353338204dc3bc6e6368656e0d0a303839203231323637322d300d0a706f73747374656c6c6540646174656e73636875747a2d62617965726e2e6465a76831660420375b6e3cc271940553c199386e13a6eab00c086ae3bce1a67e8a1e83118733c004209c7575d778fb0dba0687864a93f85b1bee48d20a72e4b8ab8d19610aab34a1500420fb9a1575bd0ce4e986f7f42a2234ce40617757135ccef19c62519a764790cfea 7f4c12060904007f00070301020253050001009904 7f4c12060904007f00070301020253050000000000 67177315060904007f00070301040253083230313830313235 D0:40:A4:CA:53:1E:5B:FF:21:25:C7:82:3F:FE:6E:5A 2018-01-25 10:00:10,331 [PAOS] DEBUG org.openecard.transport.paos.PAOS:209 - Message received: urn:uuid:bf7a0269-c9b4-4da8-8fc5-816b9624669a urn:uuid:24072141-9029-4b8b-b89f-a5ef9da7c393 H1NctFpkvY7sCUUpPBSegA 0C4CFAEE07B92B3DB449BBD1F144DC09 REINER SCT cyberJack RFID standard (0810057893) 00 00 0 3F00 874B4EF35DD1A3A87611A06D91439BA8E983AE516CDE2ABE http://bsi.bund.de/cif/npa.xml PIN 7f218201487f4e8201005f2901004210444544566549444454523130313433317f494f060a04007f000702020202038641048650ffb363aca465ceddff921455e7d8b40b46668f44ef3f6129d1e654e99a2c6caba42ea553b9bcc3143794b8b5be76535d1493ffe93f8d69b0824eaa44b94c5f200e44453030303035313030303035337f4c12060904007f0007030102025305000101db045f25060108000102055f2406010800010206655e732d060904007f00070301030280202f7f530240110ee0adfcaba5bce97e9a44bab167b5677e42b002192a9d238945732d060904007f0007030103018020cde462c123ef567854d77ed12df1183bbcecae8279b4abd5020016b4fe22fa535f374053a0b7cbec3bcc4a95565963137d4e188588d27b81bcb063ffbf8532b600066c97f92d8db68d6cbed4a6091533fc7a54d796c0876405bec2d88bc21fa430289b 7f218201b67f4e82016e5f290100420e44454356434165494430303130327f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a78641048925419fc7f194922cfc6b8dd25ae6a19c1b59216e6cf06270e5d75cfd64205f55cf867bbfefeefd6e680e1fd197f18ab684484901362568efc9adb5c6018d728701015f200e44454356434165494430303130337f4c12060904007f0007030102025305fc0f13ffff5f25060102010200035f24060105010200035f37404d6f08a86a4f18409f6685387dd3c6a7ff5d68ea4f7714a861bbb3bb721d05d3014adf1763c9292f715d8e94ee9b3e1b73ab1382414ebf39dfb3b0fb6c09dbeb 7f218201b67f4e82016e5f290100420e44454356434165494430303130337f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a7864104241d8627338b64f20077ffd558909a096c635ddb222852038eaae642e869a40173d588f817d95db2a6a0f077ea5ee63596a20f85bc3cb176d2f98d88d90219aa8701015f200e44454356434165494430303130347f4c12060904007f0007030102025305fc0f13ffff5f25060105000901045f24060108000901045f3740313a81ed8734e7a8c45f16b55fb603e63027b7f44c2de3a8e782552d35949db221ca33bd41a01da6a1288c7885714fc3a03fa45683b75d3884930ec6738af8a0 7f2181e77f4e81a05f290100420e44454356434165494430303130347f494f060a04007f000702020202038641048b9fbbfa2e30567e97c28f2fcfbfd0b02a129fa27654252a17af90f06d5a1edd6cd9b027145c4154148509d5bae005268d2082f8f6a1e358bdd4be98ea08439a5f2010444544566549444454523130313433317f4c12060904007f0007030102025305400513ff875f25060107010200085f24060108000300085f37403a8a1f9c4ba64edd5093953ab7a1b6a0180a689debdf22f3bad64e776b4647675bc34251fa9ff848cdb3e3ff51da73b7ded2bc70e3ef1f7520c1d41000255fd6 308202fa060a04007f00070301030101a10e0c0c442d547275737420476d6248a2181316687474703a2f2f7777772e642d74727573742e6e6574a3470c45454c53544552202d204672656973746161742042617965726e2c2076657274722e2064757263682042617953744d462c2076657274722e206475726368204261794c665374a417131568747470733a2f2f7777772e656c737465722e6465a58201f40c8201f04e616d652c20416e7363687269667420756e6420452d4d61696c2d4164726573736520646573200d0a4469656e737465616e626965746572733a0d0a454c53544552202d204672656973746161742042617965726e2c0d0a76657274722e2064757263682042617953744d462c0d0a76657274722e206475726368204261794c6653740d0a4b6174686172696e612d766f6e2d426f72612d53747261c39f6520360d0a3830333333204dc3bc6e6368656e0d0a686f746c696e6540656c737465722e64650d0a0d0a4765736368c3a46674737a7765636b3a0d0a0d0a48696e7765697320617566206469652066c3bc722064656e204469656e737465616e626965746572200d0a7a757374c3a46e646967656e205374656c6c656e2c20646965206469652045696e68616c74756e67200d0a64657220566f7273636872696674656e207a756d20446174656e73636875747a200d0a6b6f6e74726f6c6c696572656e3a0d0a4465722042617965726973636865204c616e64657362656175667472616774652066c3bc722064656e20446174656e73636875747a0d0a5761676dc3bc6c6c657273747261c39f652031380d0a3830353338204dc3bc6e6368656e0d0a303839203231323637322d300d0a706f73747374656c6c6540646174656e73636875747a2d62617965726e2e6465a76831660420375b6e3cc271940553c199386e13a6eab00c086ae3bce1a67e8a1e83118733c004209c7575d778fb0dba0687864a93f85b1bee48d20a72e4b8ab8d19610aab34a1500420fb9a1575bd0ce4e986f7f42a2234ce40617757135ccef19c62519a764790cfea 7f4c12060904007f00070301020253050001009904 7f4c12060904007f00070301020253050000000000 67177315060904007f00070301040253083230313830313235 D0:40:A4:CA:53:1E:5B:FF:21:25:C7:82:3F:FE:6E:5A 2018-01-25 10:00:10,340 [PAOS] DEBUG o.o.common.util.HandlerUtils:124 - Found ConnectionHandle in object of type DIDAuthenticate. 2018-01-25 10:00:10,363 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:10,364 [Dispatcher Event 0] DEBUG o.o.s.p.eac.gui.CardRemovedFilter:54 - Received event. 2018-01-25 10:00:10,364 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:10,364 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.DIDAuthenticate 2018-01-25 10:00:10,388 [PAOS] WARN org.openecard.common.I18n:152 - Failed to load resource eac for lang de_DE. 2018-01-25 10:00:10,432 [PAOS] DEBUG o.o.common.util.HandlerUtils:131 - Found ContextHandle in object of type GetIFDCapabilities. 2018-01-25 10:00:10,436 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:10,436 [Dispatcher Event 0] DEBUG o.o.s.p.eac.gui.CardRemovedFilter:54 - Received event. 2018-01-25 10:00:10,437 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:10,438 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.GetIFDCapabilities 2018-01-25 10:00:10,439 [PAOS] WARN o.o.ifd.scio.wrapper.ChannelManager:86 - Terminal 'REINER SCT cyberJack RFID standard (0810057893) 00 00' is already connected. 2018-01-25 10:00:10,457 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:10,458 [Dispatcher Event 0] DEBUG o.o.s.p.eac.gui.CardRemovedFilter:54 - Received event. 2018-01-25 10:00:10,459 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:10,463 [PAOS] WARN o.o.c.c.a.c.CardVerifiableCertificateChain:60 - Verification of the certificate chain is disabled. 2018-01-25 10:00:10,475 [PAOS] DEBUG o.o.common.util.TR03112Utils:104 - Hash of the retrieved server certificate: FB9A1575BD0CE4E986F7F42A2234CE40617757135CCEF19C62519A764790CFEA 2018-01-25 10:00:10,476 [PAOS] DEBUG o.o.common.util.TR03112Utils:109 - CommCertificate: 375B6E3CC271940553C199386E13A6EAB00C086AE3BCE1A67E8A1E83118733C0 2018-01-25 10:00:10,478 [PAOS] DEBUG o.o.common.util.TR03112Utils:109 - CommCertificate: 9C7575D778FB0DBA0687864A93F85B1BEE48D20A72E4B8AB8D19610AAB34A150 2018-01-25 10:00:10,479 [PAOS] DEBUG o.o.common.util.TR03112Utils:109 - CommCertificate: FB9A1575BD0CE4E986F7F42A2234CE40617757135CCEF19C62519A764790CFEA 2018-01-25 10:00:10,484 [PAOS] DEBUG o.o.common.util.TR03112Utils:104 - Hash of the retrieved server certificate: 375B6E3CC271940553C199386E13A6EAB00C086AE3BCE1A67E8A1E83118733C0 2018-01-25 10:00:10,485 [PAOS] DEBUG o.o.common.util.TR03112Utils:109 - CommCertificate: 375B6E3CC271940553C199386E13A6EAB00C086AE3BCE1A67E8A1E83118733C0 2018-01-25 10:00:10,490 [PAOS] DEBUG o.o.common.util.TR03112Utils:104 - Hash of the retrieved server certificate: 9C7575D778FB0DBA0687864A93F85B1BEE48D20A72E4B8AB8D19610AAB34A150 2018-01-25 10:00:10,491 [PAOS] DEBUG o.o.common.util.TR03112Utils:109 - CommCertificate: 375B6E3CC271940553C199386E13A6EAB00C086AE3BCE1A67E8A1E83118733C0 2018-01-25 10:00:10,494 [PAOS] DEBUG o.o.common.util.TR03112Utils:109 - CommCertificate: 9C7575D778FB0DBA0687864A93F85B1BEE48D20A72E4B8AB8D19610AAB34A150 2018-01-25 10:00:10,497 [PAOS] DEBUG o.o.common.util.TR03112Utils:104 - Hash of the retrieved server certificate: 9C7575D778FB0DBA0687864A93F85B1BEE48D20A72E4B8AB8D19610AAB34A150 2018-01-25 10:00:10,498 [PAOS] DEBUG o.o.common.util.TR03112Utils:109 - CommCertificate: 375B6E3CC271940553C199386E13A6EAB00C086AE3BCE1A67E8A1E83118733C0 2018-01-25 10:00:10,499 [PAOS] DEBUG o.o.common.util.TR03112Utils:109 - CommCertificate: 9C7575D778FB0DBA0687864A93F85B1BEE48D20A72E4B8AB8D19610AAB34A150 2018-01-25 10:00:10,505 [PAOS] DEBUG o.o.common.util.TR03112Utils:54 - Checking SOP for https://www.elster.de/eportal/registrierung-auswahl/eid-fwd/JA0?ElsterRequestKeys.NPA_REG_ID=f9601f51-99bd-4b25-9f76-ff98768ece05 and https://www.elster.de. 2018-01-25 10:00:10,526 [PAOS] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Transmit. 2018-01-25 10:00:10,540 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:10,541 [Dispatcher Event 0] DEBUG o.o.s.p.eac.gui.CardRemovedFilter:54 - Received event. 2018-01-25 10:00:10,542 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:10,542 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit 2018-01-25 10:00:10,545 [PAOS] DEBUG o.o.i.s.wrapper.SingleThreadChannel:260 - Send APDU: 0x00 0x22 0xC1 0xA4 0x0F 0x80 0x0A 0x04 0x00 0x7F 0x00 0x07 0x02 0x02 0x04 0x02 0x02 0x83 0x01 0x03 2018-01-25 10:00:10,604 [PAOS] DEBUG o.o.i.s.wrapper.SingleThreadChannel:263 - Receive APDU: 0x90 0x00 2018-01-25 10:00:10,615 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:10,615 [Dispatcher Event 0] DEBUG o.o.s.p.eac.gui.CardRemovedFilter:54 - Received event. 2018-01-25 10:00:10,615 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:10,764 [EAC-GUI] DEBUG org.openecard.gui.swing.StepBar:97 - Selecting index 0, previous was -1. 2018-01-25 10:00:10,841 [EAC-GUI] WARN org.openecard.common.I18n:152 - Failed to load resource swing for lang de_DE. 2018-01-25 10:00:11,026 [Swing-GUI-BG-Task] DEBUG o.o.s.protocol.eac.gui.CardMonitor:65 - Waiting for card to be removed. 2018-01-25 10:00:16,076 [AWT-EventQueue-1] DEBUG o.o.gui.swing.SwingNavigator:244 - Received event: Button.next 2018-01-25 10:00:16,082 [AWT-EventQueue-1] DEBUG org.openecard.gui.swing.StepFrame:257 - Trying to kill background task if it exists. 2018-01-25 10:00:16,083 [AWT-EventQueue-1] DEBUG org.openecard.gui.swing.StepFrame:260 - Killing background task. 2018-01-25 10:00:16,083 [Swing-GUI-BG-Task] DEBUG o.o.s.protocol.eac.gui.CardMonitor:76 - Card has not been removed. 2018-01-25 10:00:16,083 [AWT-EventQueue-1] DEBUG org.openecard.gui.swing.StepFrame:222 - Exchange result for step 'Anbieter'. 2018-01-25 10:00:16,084 [Swing-GUI-BG-Task] DEBUG org.openecard.gui.swing.StepFrame$1:276 - Background task has been terminated from the Swing GUI. java.lang.InterruptedException: null at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1039) at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328) at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277) at org.openecard.common.util.Promise.deref(Promise.java:145) at org.openecard.common.util.Promise.deref(Promise.java:125) at org.openecard.sal.protocol.eac.gui.CardMonitor.call(CardMonitor.java:66) at org.openecard.sal.protocol.eac.gui.CardMonitor.call(CardMonitor.java:47) at org.openecard.gui.swing.StepFrame$1.run(StepFrame.java:272) at java.lang.Thread.run(Thread.java:748) 2018-01-25 10:00:16,099 [EAC-GUI] DEBUG org.openecard.gui.swing.StepBar:97 - Selecting index 1, previous was 0. 2018-01-25 10:00:16,181 [Swing-GUI-BG-Task] DEBUG o.o.s.protocol.eac.gui.CardMonitor:65 - Waiting for card to be removed. 2018-01-25 10:00:18,997 [AWT-EventQueue-1] DEBUG o.o.gui.swing.SwingNavigator:244 - Received event: Button.next 2018-01-25 10:00:19,001 [AWT-EventQueue-1] DEBUG org.openecard.gui.swing.StepFrame:257 - Trying to kill background task if it exists. 2018-01-25 10:00:19,001 [AWT-EventQueue-1] DEBUG org.openecard.gui.swing.StepFrame:260 - Killing background task. 2018-01-25 10:00:19,002 [Swing-GUI-BG-Task] DEBUG o.o.s.protocol.eac.gui.CardMonitor:76 - Card has not been removed. 2018-01-25 10:00:19,003 [Swing-GUI-BG-Task] DEBUG org.openecard.gui.swing.StepFrame$1:276 - Background task has been terminated from the Swing GUI. java.lang.InterruptedException: null at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1039) at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328) at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277) at org.openecard.common.util.Promise.deref(Promise.java:145) at org.openecard.common.util.Promise.deref(Promise.java:125) at org.openecard.sal.protocol.eac.gui.CardMonitor.call(CardMonitor.java:66) at org.openecard.sal.protocol.eac.gui.CardMonitor.call(CardMonitor.java:47) at org.openecard.gui.swing.StepFrame$1.run(StepFrame.java:272) at java.lang.Thread.run(Thread.java:748) 2018-01-25 10:00:19,003 [AWT-EventQueue-1] DEBUG org.openecard.gui.swing.StepFrame:222 - Exchange result for step 'Angefragte Daten'. 2018-01-25 10:00:19,023 [EAC-GUI] DEBUG org.openecard.gui.swing.StepBar:97 - Selecting index 2, previous was 1. 2018-01-25 10:00:19,079 [Swing-GUI-BG-Task] DEBUG o.o.s.protocol.eac.gui.CardMonitor:65 - Waiting for card to be removed. 2018-01-25 10:00:19,096 [Instant-Return-Thread-2] DEBUG o.o.gui.swing.SwingNavigator:244 - Received event: Button.next 2018-01-25 10:00:19,097 [Instant-Return-Thread-2] DEBUG org.openecard.gui.swing.StepFrame:257 - Trying to kill background task if it exists. 2018-01-25 10:00:19,098 [Instant-Return-Thread-2] DEBUG org.openecard.gui.swing.StepFrame:260 - Killing background task. 2018-01-25 10:00:19,098 [Swing-GUI-BG-Task] DEBUG o.o.s.protocol.eac.gui.CardMonitor:76 - Card has not been removed. 2018-01-25 10:00:19,098 [Swing-GUI-BG-Task] DEBUG org.openecard.gui.swing.StepFrame$1:276 - Background task has been terminated from the Swing GUI. java.lang.InterruptedException: null at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1039) at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328) at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277) at org.openecard.common.util.Promise.deref(Promise.java:145) at org.openecard.common.util.Promise.deref(Promise.java:125) at org.openecard.sal.protocol.eac.gui.CardMonitor.call(CardMonitor.java:66) at org.openecard.sal.protocol.eac.gui.CardMonitor.call(CardMonitor.java:47) at org.openecard.gui.swing.StepFrame$1.run(StepFrame.java:272) at java.lang.Thread.run(Thread.java:748) 2018-01-25 10:00:19,101 [Instant-Return-Thread-2] DEBUG org.openecard.gui.swing.StepFrame:222 - Exchange result for step 'PIN-Eingabe'. 2018-01-25 10:00:19,132 [pool-6-thread-1] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type EstablishChannel. 2018-01-25 10:00:19,164 [pool-6-thread-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:19,171 [Dispatcher Event 0] DEBUG o.o.s.p.eac.gui.CardRemovedFilter:54 - Received event. 2018-01-25 10:00:19,172 [Dispatcher Event 0] DEBUG o.o.s.p.eac.gui.CardRemovedFilter:54 - Received event. 2018-01-25 10:00:19,173 [pool-6-thread-1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:19,173 [pool-6-thread-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.EstablishChannel 2018-01-25 10:00:19,203 [pool-6-thread-1] DEBUG org.openecard.ifd.scio.IFD:1067 - executeCtrlCode request: 02180303157F4C12060904007F0007030102025305000100990400FE02308202FA060A04007F00070301030101A10E0C0C442D547275737420476D6248A2181316687474703A2F2F7777772E642D74727573742E6E6574A3470C45454C53544552202D204672656973746161742042617965726E2C2076657274722E2064757263682042617953744D462C2076657274722E206475726368204261794C665374A417131568747470733A2F2F7777772E656C737465722E6465A58201F40C8201F04E616D652C20416E7363687269667420756E6420452D4D61696C2D4164726573736520646573200D0A4469656E737465616E626965746572733A0D0A454C53544552202D204672656973746161742042617965726E2C0D0A76657274722E2064757263682042617953744D462C0D0A76657274722E206475726368204261794C6653740D0A4B6174686172696E612D766F6E2D426F72612D53747261C39F6520360D0A3830333333204DC3BC6E6368656E0D0A686F746C696E6540656C737465722E64650D0A0D0A4765736368C3A46674737A7765636B3A0D0A0D0A48696E7765697320617566206469652066C3BC722064656E204469656E737465616E626965746572200D0A7A757374C3A46E646967656E205374656C6C656E2C20646965206469652045696E68616C74756E67200D0A64657220566F7273636872696674656E207A756D20446174656E73636875747A200D0A6B6F6E74726F6C6C696572656E3A0D0A4465722042617965726973636865204C616E64657362656175667472616774652066C3BC722064656E20446174656E73636875747A0D0A5761676DC3BC6C6C657273747261C39F652031380D0A3830353338204DC3BC6E6368656E0D0A303839203231323637322D300D0A706F73747374656C6C6540646174656E73636875747A2D62617965726E2E6465A76831660420375B6E3CC271940553C199386E13A6EAB00C086AE3BCE1A67E8A1E83118733C004209C7575D778FB0DBA0687864A93F85B1BEE48D20A72E4B8AB8D19610AAB34A1500420FB9A1575BD0CE4E986F7F42A2234CE40617757135CCEF19C62519A764790CFEA 2018-01-25 10:00:39,167 [SCIO Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:404 - No service available exception, reloading PCSC. 2018-01-25 10:00:39,186 [pool-6-thread-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:39,187 [Dispatcher Event 0] DEBUG o.o.s.p.eac.gui.CardRemovedFilter:54 - Received event. 2018-01-25 10:00:39,187 [Dispatcher Event 0] DEBUG o.o.s.p.eac.gui.CardRemovedFilter:54 - Received event. 2018-01-25 10:00:39,187 [pool-6-thread-1] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:39,190 [pool-6-thread-1] ERROR o.o.s.p.eac.gui.PINStepAction:223 - An unknown error occured while trying to verify the PIN. 2018-01-25 10:00:39,211 [EAC-GUI] DEBUG org.openecard.gui.swing.StepBar:97 - Selecting index 2, previous was 2. 2018-01-25 10:00:39,217 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event. 2018-01-25 10:00:39,218 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_FINISHED into event queue. 2018-01-25 10:00:39,219 [PAOS] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request (before adding content): POST /ecardpaos/paosreceiver HTTP/1.1 Connection: keep-alive User-Agent: Open eCard App/org.openecard.common.SemanticVersion@e580929 Host: eidpaos.elsteronline.de PAOS: ver="urn:liberty:paos:2006-08" ;"urn:iso:std:iso-iec:24727:tech:schema:Transmit";"http://www.bsi.bund.de/ecard/api/1.0#InitializeFramework";"urn:iso:std:iso-iec:24727:tech:schema:StartSession";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationEndSession";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationList";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationServiceList";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationServiceDescribe";"urn:iso:std:iso-iec:24727:tech:schema:DataSetList";"urn:iso:std:iso-iec:24727:tech:schema:DataSetSelect";"urn:iso:std:iso-iec:24727:tech:schema:DSIList";"urn:iso:std:iso-iec:24727:tech:schema:DSIWrite";"urn:iso:std:iso-iec:24727:tech:schema:DSIRead";"urn:iso:std:iso-iec:24727:tech:schema:Encipher";"urn:iso:std:iso-iec:24727:tech:schema:Decipher";"urn:iso:std:iso-iec:24727:tech:schema:GetRandom";"urn:iso:std:iso-iec:24727:tech:schema:Sign";"urn:iso:std:iso-iec:24727:tech:schema:VerifySignature";"urn:iso:std:iso-iec:24727:tech:schema:VerifyCertificate";"urn:iso:std:iso-iec:24727:tech:schema:DIDList";"urn:iso:std:iso-iec:24727:tech:schema:DIDGet";"urn:iso:std:iso-iec:24727:tech:schema:DIDAuthenticate";"urn:iso:std:iso-iec:24727:tech:schema:ACLList";"urn:iso:std:iso-iec:24727:tech:schema:Hash" Accept: text/xml, application/xml, application/vnd.paos+xml 2018-01-25 10:00:39,221 [Dispatcher Event 0] DEBUG o.o.s.p.eac.gui.CardRemovedFilter:54 - Received event. 2018-01-25 10:00:39,223 [Dispatcher Event 0] DEBUG o.o.s.p.eac.gui.CardRemovedFilter:54 - Received event. 2018-01-25 10:00:39,224 [PAOS] DEBUG org.openecard.transport.paos.PAOS:234 - Message sent:
urn:liberty:paos:2006-08
http://www.projectliberty.org/2006/01/role/paos
http://www.bsi.bund.de/ecard/api/1.1/PAOS/GetNextCommand
http://www.projectliberty.org/2006/02/role/paos
 urn:uuid:24072141-9029-4b8b-b89f-a5ef9da7c393 urn:uuid:00634a2e-d24e-4d49-9fdb-dc80972f7b13
http://www.bsi.bund.de/ecard/api/1.1/resultmajor#error http://www.bsi.bund.de/ecard/api/1.1/resultminor/al/common#unknownError Failed to transmit control command to the terminal 'REINER SCT cyberJack RFID standard (0810057893) 00 00'. 2018-01-25 10:00:39,224 [PAOS] DEBUG org.openecard.transport.paos.PAOS:318 - Sending HTTP request. 2018-01-25 10:00:39,258 [Instant-Return-Thread-3] DEBUG o.o.gui.swing.SwingNavigator:244 - Received event: Button.next 2018-01-25 10:00:39,262 [Instant-Return-Thread-3] DEBUG org.openecard.gui.swing.StepFrame:257 - Trying to kill background task if it exists. 2018-01-25 10:00:39,263 [Instant-Return-Thread-3] DEBUG org.openecard.gui.swing.StepFrame:222 - Exchange result for step 'Fehler'. 2018-01-25 10:00:39,280 [EAC-GUI] INFO o.o.gui.executor.ExecutionEngine:180 - StepAction was canceled. 2018-01-25 10:00:39,471 [PAOS] DEBUG org.openecard.transport.paos.PAOS:320 - HTTP response received. 2018-01-25 10:00:39,471 [PAOS] WARN org.openecard.transport.paos.PAOS:424 - The PAOS endpoint sent the http status code 200 which does not conform to the PAOS specification. (See section 9.4 Processing Rules of the PAOS Specification) 2018-01-25 10:00:39,472 [PAOS] DEBUG o.o.transport.httpcore.HttpUtils:112 - HTTP Response: HTTP/1.1 200 OK Server: Apache-Coyote/1.1 Content-Security-Policy: default-src 'self' Content-Type: application/vnd.paos+xml Content-Length: 1195 Date: Thu, 25 Jan 2018 09:00:39 GMT urn:uuid:00634a2e-d24e-4d49-9fdb-dc80972f7b13 urn:uuid:169b6161-e39d-458c-9182-65d81363adf1 http://www.bsi.bund.de/ecard/api/1.1/resultmajor#error http://www.bsi.bund.de/ecard/api/1.1/resultminor/al/common#unknownError Failed to transmit control command to the terminal 'REINER SCT cyberJack RFID standard (0810057893) 00 00'. 2018-01-25 10:00:39,475 [PAOS] DEBUG org.openecard.transport.paos.PAOS:209 - Message received: urn:uuid:00634a2e-d24e-4d49-9fdb-dc80972f7b13 urn:uuid:169b6161-e39d-458c-9182-65d81363adf1 http://www.bsi.bund.de/ecard/api/1.1/resultmajor#error http://www.bsi.bund.de/ecard/api/1.1/resultminor/al/common#unknownError Failed to transmit control command to the terminal 'REINER SCT cyberJack RFID standard (0810057893) 00 00'. 2018-01-25 10:00:39,478 [PAOS] INFO o.o.c.tls.ClientCertPSKTlsClient:262 - TLS warning sent. 2018-01-25 10:00:39,479 [PAOS] INFO o.o.c.tls.ClientCertPSKTlsClient:264 - TLS(WARN): Close [close_notify=0] --> Connection closed 2018-01-25 10:00:39,480 [PAOS] DEBUG o.o.common.util.HandlerUtils:124 - Found ConnectionHandle in object of type CardApplicationDisconnect. 2018-01-25 10:00:39,483 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:39,483 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:39,483 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.CardApplicationDisconnect 2018-01-25 10:00:39,484 [PAOS] DEBUG o.o.common.util.HandlerUtils:144 - Found SlotHandle in object of type Disconnect. 2018-01-25 10:00:39,487 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event. 2018-01-25 10:00:39,488 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:124 - Added event API_CALL_STARTED into event queue. 2018-01-25 10:00:39,488 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Disconnect 2018-01-25 10:02:50,216 [AWT-EventQueue-1] DEBUG o.openecard.richclient.gui.Status$1:165 - Shutdown button pressed.