Project

General

Profile

Bug #771 » richclient_info.log

Detlef Hühnlein, 09/28/2019 06:22 PM

 
1
2019-09-28 18:06:28,225+02 [main] INFO  o.o.richclient.LogbackConfig:81 - Configured Logback with config file from: C:\Users\H?hni\.openecard\richclient_logback.xml
2
2019-09-28 18:06:28,231+02 [main] WARN  org.openecard.common.I18n:152 - Failed to load resource ifd for lang C.
3
2019-09-28 18:06:28,231+02 [main] WARN  org.openecard.common.I18n:152 - Failed to load resource ifd for lang de.
4
2019-09-28 18:06:28,231+02 [main] WARN  org.openecard.common.I18n:152 - Failed to load resource ifd for lang de_DE.
5
2019-09-28 18:06:28,232+02 [main] WARN  org.openecard.common.I18n:152 - Failed to load resource sal for lang C.
6
2019-09-28 18:06:28,240+02 [main] WARN  org.openecard.common.I18n:152 - Failed to load resource sal for lang de.
7
2019-09-28 18:06:28,240+02 [main] WARN  org.openecard.common.I18n:152 - Failed to load resource sal for lang de_DE.
8
2019-09-28 18:06:28,241+02 [main] WARN  org.openecard.common.I18n:152 - Failed to load resource richclient for lang de_DE.
9
2019-09-28 18:06:28,243+02 [main] INFO  org.openecard.richclient.RichClient:145 - Starting Open eCard App 1.3.0 ...
10
2019-09-28 18:06:28,591+02 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:98 - Loading middleware config.
11
2019-09-28 18:06:28,592+02 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:135 - Reading middleware config from XML file.
12
2019-09-28 18:06:28,620+02 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:149 - CardImageName: rub-card.png
13
2019-09-28 18:06:28,621+02 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:149 - CardImageName: luxtrust-v3.jpg
14
2019-09-28 18:06:28,623+02 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:149 - CardImageName: Lux-eID.jpg
15
2019-09-28 18:06:28,623+02 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:149 - CardImageName: ihk-card.jpg
16
2019-09-28 18:06:28,624+02 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:149 - CardImageName: portuguese-eid.png
17
2019-09-28 18:06:28,626+02 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:149 - CardImageName: SafeNet-eToken.jpg
18
2019-09-28 18:06:28,626+02 [main] DEBUG o.o.m.sal.config.MiddlewareConfig:149 - CardImageName: GeoEID.jpg
19
2019-09-28 18:06:28,639+02 [main] WARN  org.openecard.common.I18n:152 - Failed to load resource recognition for lang de_DE.
20
2019-09-28 18:06:28,641+02 [Init-CardInfo-Repo] INFO  o.o.recognition.CardRecognitionImpl:128 - Initializing CIF Repo.
21
2019-09-28 18:06:28,643+02 [Init-RecognitionTree-Repo] INFO  o.o.recognition.CardRecognitionImpl:146 - Initializing RecognitionTree Repo.
22
2019-09-28 18:06:28,771+02 [Init-File-Addons] DEBUG org.openecard.addon.FileRegistry:144 - Starting addon filesystem monitor on path: C:\Users\H?hni\.openecard\addons
23
2019-09-28 18:06:28,802+02 [Init-Classpath-Addons] INFO  o.openecard.addon.ClasspathRegistry:94 - Loaded internal TR-03112 add-on.
24
2019-09-28 18:06:28,812+02 [Init-Classpath-Addons] INFO  o.openecard.addon.ClasspathRegistry:94 - Loaded internal ChipGateway add-on.
25
2019-09-28 18:06:28,822+02 [Init-Classpath-Addons] INFO  o.openecard.addon.ClasspathRegistry:94 - Loaded internal PIN-Management add-on.
26
2019-09-28 18:06:28,824+02 [Init-Classpath-Addons] INFO  o.openecard.addon.ClasspathRegistry:94 - Loaded internal GenericCrypto add-on.
27
2019-09-28 18:06:28,826+02 [Init-Classpath-Addons] INFO  o.openecard.addon.ClasspathRegistry:94 - Loaded internal Status add-on.
28
2019-09-28 18:06:28,826+02 [Init-Classpath-Addons] WARN  o.openecard.addon.ClasspathRegistry:89 - Skipped loading internal add-on PKCS#11, because it is not available.
29
2019-09-28 18:06:28,924+02 [Init-CardInfo-Repo] DEBUG o.o.recognition.CardRecognitionImpl:134 - Done loading CIF documents.
30
2019-09-28 18:06:28,925+02 [Init-CardInfo-Repo] DEBUG o.o.recognition.CardRecognitionImpl:138 - Done determining supported cards.
31
2019-09-28 18:06:28,925+02 [Init-CardInfo-Repo] INFO  o.o.recognition.CardRecognitionImpl:140 - Finished initializing CIF Repo.
32
2019-09-28 18:06:29,474+02 [main] DEBUG org.openecard.richclient.RichClient:234 - Checking if dispatcher mode should be used.
33
2019-09-28 18:06:29,520+02 [main] WARN  org.openecard.common.I18n:152 - Failed to load resource http for lang de_DE.
34
2019-09-28 18:06:29,526+02 [main] DEBUG o.o.c.binding.http.HttpService:76 - Starting HTTP Binding on port 24727
35
2019-09-28 18:06:29,529+02 [main] DEBUG o.o.c.binding.http.HttpService:88 - Add handler [org.openecard.control.binding.http.handler.HttpAppPluginActionHandler] for ID [*]
36
2019-09-28 18:06:29,756+02 [main] INFO  o.o.mdlw.sal.MiddleWareWrapper:94 - Loading Middleware LuxTrust: Library=gclib
37
2019-09-28 18:06:29,778+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_Initialize.
38
2019-09-28 18:06:29,816+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_Initialize: 0x00000000 -> CKR_OK, duration=0.035s
39
2019-09-28 18:06:29,820+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetSlotList.
40
2019-09-28 18:06:29,847+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetSlotList: 0x00000000 -> CKR_OK, duration=0.027s
41
2019-09-28 18:06:29,850+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetSlotList.
42
2019-09-28 18:06:29,854+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetSlotList: 0x00000000 -> CKR_OK, duration=0.003s
43
2019-09-28 18:06:29,857+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetSlotInfo.
44
2019-09-28 18:06:29,858+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetSlotInfo: 0x00000000 -> CKR_OK, duration=0.001s
45
2019-09-28 18:06:29,859+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetSlotInfo.
46
2019-09-28 18:06:29,859+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetSlotInfo: 0x00000000 -> CKR_OK, duration=0.000s
47
2019-09-28 18:06:29,859+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetSlotInfo.
48
2019-09-28 18:06:29,860+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetSlotInfo: 0x00000000 -> CKR_OK, duration=0.000s
49
2019-09-28 18:06:29,860+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetSlotInfo.
50
2019-09-28 18:06:29,861+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetSlotInfo: 0x00000000 -> CKR_OK, duration=0.000s
51
2019-09-28 18:06:29,861+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetSlotInfo.
52
2019-09-28 18:06:29,861+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetSlotInfo: 0x00000000 -> CKR_OK, duration=0.000s
53
2019-09-28 18:06:29,862+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:220 - Sending TERMINAL_ADDED event, ifdName=Alcor Micro USB Smart Card Reader 0 id=1.
54
2019-09-28 18:06:29,862+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:485 - Notify TERMINAL_ADDED, MwEventObject={ifdName=Alcor Micro USB Smart Card Reader 0, slot=null, cardType=null}
55
2019-09-28 18:06:29,862+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
56
2019-09-28 18:06:29,864+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.addon.EventHandler@ea6137.
57
2019-09-28 18:06:29,865+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
58
2019-09-28 18:06:29,866+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: TERMINAL_ADDED
59
2019-09-28 18:06:29,867+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetTokenInfo.
60
2019-09-28 18:06:29,868+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=Alcor Micro USB Smart Card Reader 0, slot=null, ctx=49FE1F790982121D9FCEFEEB8ACF0606
61
2019-09-28 18:06:29,868+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetTokenInfo: 0x00000032 -> CKR_DEVICE_REMOVED, duration=0.001s
62
2019-09-28 18:06:29,868+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:394 - RecognitionInfo: null
63
2019-09-28 18:06:29,869+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:96 - Error getting token information, no card present in the requested slot.
64
org.openecard.mdlw.sal.exceptions.SessionException: [CKR_DEVICE_REMOVED] The token was removed from its slot during the execution of the function.
65
	at org.openecard.mdlw.sal.MiddleWareWrapper.raiseError(MiddleWareWrapper.java:601)
66
	at org.openecard.mdlw.sal.MiddleWareWrapper.check(MiddleWareWrapper.java:540)
67
	at org.openecard.mdlw.sal.MiddleWareWrapper.check(MiddleWareWrapper.java:545)
68
	at org.openecard.mdlw.sal.MiddleWareWrapper.getTokenInfo(MiddleWareWrapper.java:283)
69
	at org.openecard.mdlw.sal.MwSlot.getTokenInfo(MwSlot.java:72)
70
	at org.openecard.mdlw.event.MwEventRunner.initRunner(MwEventRunner.java:90)
71
	at org.openecard.mdlw.event.MwEventManager.initialize(MwEventManager.java:75)
72
	at org.openecard.mdlw.sal.MiddlewareSAL.initialize(MiddlewareSAL.java:321)
73
	at org.openecard.sal.SelectorSAL.initialize(SelectorSAL.java:258)
74
	at org.openecard.richclient.RichClient.setup(RichClient.java:286)
75
	at org.openecard.richclient.RichClient.main(RichClient.java:148)
76
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
77
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
78
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
79
	at java.lang.reflect.Method.invoke(Unknown Source)
80
	at org.openecard.versioncheck.MainLoader.main(MainLoader.java:73)
81
2019-09-28 18:06:29,870+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
82
2019-09-28 18:06:29,870+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:220 - Sending TERMINAL_ADDED event, ifdName=DATEV Virtueller SmartCard Leser 0 id=2.
83
2019-09-28 18:06:29,870+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:485 - Notify TERMINAL_ADDED, MwEventObject={ifdName=DATEV Virtueller SmartCard Leser 0, slot=null, cardType=null}
84
2019-09-28 18:06:29,870+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
85
2019-09-28 18:06:29,870+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.addon.EventHandler@ea6137.
86
2019-09-28 18:06:29,870+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
87
2019-09-28 18:06:29,870+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetTokenInfo.
88
2019-09-28 18:06:29,872+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetTokenInfo: 0x00000032 -> CKR_DEVICE_REMOVED, duration=0.001s
89
2019-09-28 18:06:29,872+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:96 - Error getting token information, no card present in the requested slot.
90
org.openecard.mdlw.sal.exceptions.SessionException: [CKR_DEVICE_REMOVED] The token was removed from its slot during the execution of the function.
91
	at org.openecard.mdlw.sal.MiddleWareWrapper.raiseError(MiddleWareWrapper.java:601)
92
	at org.openecard.mdlw.sal.MiddleWareWrapper.check(MiddleWareWrapper.java:540)
93
	at org.openecard.mdlw.sal.MiddleWareWrapper.check(MiddleWareWrapper.java:545)
94
	at org.openecard.mdlw.sal.MiddleWareWrapper.getTokenInfo(MiddleWareWrapper.java:283)
95
	at org.openecard.mdlw.sal.MwSlot.getTokenInfo(MwSlot.java:72)
96
	at org.openecard.mdlw.event.MwEventRunner.initRunner(MwEventRunner.java:90)
97
	at org.openecard.mdlw.event.MwEventManager.initialize(MwEventManager.java:75)
98
	at org.openecard.mdlw.sal.MiddlewareSAL.initialize(MiddlewareSAL.java:321)
99
	at org.openecard.sal.SelectorSAL.initialize(SelectorSAL.java:258)
100
	at org.openecard.richclient.RichClient.setup(RichClient.java:286)
101
	at org.openecard.richclient.RichClient.main(RichClient.java:148)
102
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
103
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
104
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
105
	at java.lang.reflect.Method.invoke(Unknown Source)
106
	at org.openecard.versioncheck.MainLoader.main(MainLoader.java:73)
107
2019-09-28 18:06:29,872+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:220 - Sending TERMINAL_ADDED event, ifdName=DATEV Virtueller SmartCard Replikator 0 id=3.
108
2019-09-28 18:06:29,872+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:485 - Notify TERMINAL_ADDED, MwEventObject={ifdName=DATEV Virtueller SmartCard Replikator 0, slot=null, cardType=null}
109
2019-09-28 18:06:29,873+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
110
2019-09-28 18:06:29,873+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.addon.EventHandler@ea6137.
111
2019-09-28 18:06:29,873+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
112
2019-09-28 18:06:29,874+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetTokenInfo.
113
2019-09-28 18:06:29,875+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetTokenInfo: 0x00000032 -> CKR_DEVICE_REMOVED, duration=0.001s
114
2019-09-28 18:06:29,876+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:96 - Error getting token information, no card present in the requested slot.
115
org.openecard.mdlw.sal.exceptions.SessionException: [CKR_DEVICE_REMOVED] The token was removed from its slot during the execution of the function.
116
	at org.openecard.mdlw.sal.MiddleWareWrapper.raiseError(MiddleWareWrapper.java:601)
117
	at org.openecard.mdlw.sal.MiddleWareWrapper.check(MiddleWareWrapper.java:540)
118
	at org.openecard.mdlw.sal.MiddleWareWrapper.check(MiddleWareWrapper.java:545)
119
	at org.openecard.mdlw.sal.MiddleWareWrapper.getTokenInfo(MiddleWareWrapper.java:283)
120
	at org.openecard.mdlw.sal.MwSlot.getTokenInfo(MwSlot.java:72)
121
	at org.openecard.mdlw.event.MwEventRunner.initRunner(MwEventRunner.java:90)
122
	at org.openecard.mdlw.event.MwEventManager.initialize(MwEventManager.java:75)
123
	at org.openecard.mdlw.sal.MiddlewareSAL.initialize(MiddlewareSAL.java:321)
124
	at org.openecard.sal.SelectorSAL.initialize(SelectorSAL.java:258)
125
	at org.openecard.richclient.RichClient.setup(RichClient.java:286)
126
	at org.openecard.richclient.RichClient.main(RichClient.java:148)
127
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
128
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
129
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
130
	at java.lang.reflect.Method.invoke(Unknown Source)
131
	at org.openecard.versioncheck.MainLoader.main(MainLoader.java:73)
132
2019-09-28 18:06:29,876+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:220 - Sending TERMINAL_ADDED event, ifdName=DATEV Virtueller SmartCard Replikator 1 id=4.
133
2019-09-28 18:06:29,876+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:485 - Notify TERMINAL_ADDED, MwEventObject={ifdName=DATEV Virtueller SmartCard Replikator 1, slot=null, cardType=null}
134
2019-09-28 18:06:29,877+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
135
2019-09-28 18:06:29,877+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.addon.EventHandler@ea6137.
136
2019-09-28 18:06:29,877+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
137
2019-09-28 18:06:29,878+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetTokenInfo.
138
2019-09-28 18:06:29,879+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetTokenInfo: 0x00000032 -> CKR_DEVICE_REMOVED, duration=0.001s
139
2019-09-28 18:06:29,879+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:96 - Error getting token information, no card present in the requested slot.
140
org.openecard.mdlw.sal.exceptions.SessionException: [CKR_DEVICE_REMOVED] The token was removed from its slot during the execution of the function.
141
	at org.openecard.mdlw.sal.MiddleWareWrapper.raiseError(MiddleWareWrapper.java:601)
142
	at org.openecard.mdlw.sal.MiddleWareWrapper.check(MiddleWareWrapper.java:540)
143
	at org.openecard.mdlw.sal.MiddleWareWrapper.check(MiddleWareWrapper.java:545)
144
	at org.openecard.mdlw.sal.MiddleWareWrapper.getTokenInfo(MiddleWareWrapper.java:283)
145
	at org.openecard.mdlw.sal.MwSlot.getTokenInfo(MwSlot.java:72)
146
	at org.openecard.mdlw.event.MwEventRunner.initRunner(MwEventRunner.java:90)
147
	at org.openecard.mdlw.event.MwEventManager.initialize(MwEventManager.java:75)
148
	at org.openecard.mdlw.sal.MiddlewareSAL.initialize(MiddlewareSAL.java:321)
149
	at org.openecard.sal.SelectorSAL.initialize(SelectorSAL.java:258)
150
	at org.openecard.richclient.RichClient.setup(RichClient.java:286)
151
	at org.openecard.richclient.RichClient.main(RichClient.java:148)
152
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
153
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
154
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
155
	at java.lang.reflect.Method.invoke(Unknown Source)
156
	at org.openecard.versioncheck.MainLoader.main(MainLoader.java:73)
157
2019-09-28 18:06:29,879+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:220 - Sending TERMINAL_ADDED event, ifdName=REINER SCT cyberJack RFID basis 1 id=5.
158
2019-09-28 18:06:29,879+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:485 - Notify TERMINAL_ADDED, MwEventObject={ifdName=REINER SCT cyberJack RFID basis 1, slot=null, cardType=null}
159
2019-09-28 18:06:29,880+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
160
2019-09-28 18:06:29,880+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.addon.EventHandler@ea6137.
161
2019-09-28 18:06:29,880+02 [main] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
162
2019-09-28 18:06:29,881+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetTokenInfo.
163
2019-09-28 18:06:29,882+02 [main] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetTokenInfo: 0x00000032 -> CKR_DEVICE_REMOVED, duration=0.001s
164
2019-09-28 18:06:29,882+02 [main] DEBUG o.o.mdlw.event.MwEventRunner:96 - Error getting token information, no card present in the requested slot.
165
org.openecard.mdlw.sal.exceptions.SessionException: [CKR_DEVICE_REMOVED] The token was removed from its slot during the execution of the function.
166
	at org.openecard.mdlw.sal.MiddleWareWrapper.raiseError(MiddleWareWrapper.java:601)
167
	at org.openecard.mdlw.sal.MiddleWareWrapper.check(MiddleWareWrapper.java:540)
168
	at org.openecard.mdlw.sal.MiddleWareWrapper.check(MiddleWareWrapper.java:545)
169
	at org.openecard.mdlw.sal.MiddleWareWrapper.getTokenInfo(MiddleWareWrapper.java:283)
170
	at org.openecard.mdlw.sal.MwSlot.getTokenInfo(MwSlot.java:72)
171
	at org.openecard.mdlw.event.MwEventRunner.initRunner(MwEventRunner.java:90)
172
	at org.openecard.mdlw.event.MwEventManager.initialize(MwEventManager.java:75)
173
	at org.openecard.mdlw.sal.MiddlewareSAL.initialize(MiddlewareSAL.java:321)
174
	at org.openecard.sal.SelectorSAL.initialize(SelectorSAL.java:258)
175
	at org.openecard.richclient.RichClient.setup(RichClient.java:286)
176
	at org.openecard.richclient.RichClient.main(RichClient.java:148)
177
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
178
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
179
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
180
	at java.lang.reflect.Method.invoke(Unknown Source)
181
	at org.openecard.versioncheck.MainLoader.main(MainLoader.java:73)
182
2019-09-28 18:06:29,887+02 [MwEventManager] DEBUG o.o.mdlw.event.MwEventRunner:104 - Start event loop.
183
2019-09-28 18:06:29,887+02 [MwEventManager] DEBUG o.o.mdlw.event.MwEventRunner:109 - Waiting for Middleware event.
184
2019-09-28 18:06:29,888+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_WaitForSlotEvent.
185
2019-09-28 18:06:29,912+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: TERMINAL_ADDED
186
2019-09-28 18:06:29,913+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=DATEV Virtueller SmartCard Leser 0, slot=null, ctx=49FE1F790982121D9FCEFEEB8ACF0606
187
2019-09-28 18:06:29,913+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:394 - RecognitionInfo: null
188
2019-09-28 18:06:29,914+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
189
2019-09-28 18:06:29,921+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: TERMINAL_ADDED
190
2019-09-28 18:06:29,922+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=DATEV Virtueller SmartCard Replikator 0, slot=null, ctx=49FE1F790982121D9FCEFEEB8ACF0606
191
2019-09-28 18:06:29,922+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:394 - RecognitionInfo: null
192
2019-09-28 18:06:29,923+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
193
2019-09-28 18:06:29,928+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: TERMINAL_ADDED
194
2019-09-28 18:06:29,929+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=DATEV Virtueller SmartCard Replikator 1, slot=null, ctx=49FE1F790982121D9FCEFEEB8ACF0606
195
2019-09-28 18:06:29,929+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:394 - RecognitionInfo: null
196
2019-09-28 18:06:29,929+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
197
2019-09-28 18:06:29,934+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: TERMINAL_ADDED
198
2019-09-28 18:06:29,935+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=REINER SCT cyberJack RFID basis 1, slot=null, ctx=49FE1F790982121D9FCEFEEB8ACF0606
199
2019-09-28 18:06:29,935+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:394 - RecognitionInfo: null
200
2019-09-28 18:06:29,935+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
201
2019-09-28 18:06:29,980+02 [main] DEBUG o.o.ifd.event.IfdEventRunner:94 - Requesting terminal names.
202
2019-09-28 18:06:29,993+02 [main] DEBUG o.o.ifd.event.IfdEventRunner:100 - Requesting status for all terminals found.
203
2019-09-28 18:06:30,375+02 [main] INFO  o.o.i.s.wrapper.SingleThreadChannel:139 - Card connected with protocol T=1.
204
2019-09-28 18:06:30,431+02 [main] INFO  o.o.i.s.wrapper.SingleThreadChannel:139 - Card connected with protocol T=1.
205
2019-09-28 18:06:30,437+02 [Update-Task] INFO  o.o.common.util.VersionUpdateLoader:71 - Trying to load version list.
206
2019-09-28 18:06:30,440+02 [IFD Watcher 0] DEBUG o.o.common.util.HandlerUtils:132 - Found ContextHandle in object of type GetIFDCapabilities.
207
2019-09-28 18:06:30,951+02 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
208
2019-09-28 18:06:30,951+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
209
2019-09-28 18:06:30,951+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
210
2019-09-28 18:06:30,951+02 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.GetIFDCapabilities
211
2019-09-28 18:06:30,952+02 [IFD Watcher 0] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'Alcor Micro USB Smart Card Reader 0' is already connected.
212
2019-09-28 18:06:30,960+02 [Init-RecognitionTree-Repo] INFO  o.o.recognition.CardRecognitionImpl:159 - Finished initializing RecognitionTree Repo.
213
2019-09-28 18:06:30,962+02 [IFD Watcher 0] WARN  o.o.ifd.scio.wrapper.TerminalInfo:323 - Unable to request features from reader.
214
org.openecard.common.ifd.scio.SCIOException: Failed to transmit control command to the terminal 'Alcor Micro USB Smart Card Reader 0'.
215
	at org.openecard.scio.PCSCCard.transmitControlCommand(PCSCCard.java:110)
216
	at org.openecard.ifd.scio.wrapper.SingleThreadChannel.lambda$transmitControlCommand$2(SingleThreadChannel.java:288)
217
	at java.util.concurrent.FutureTask.run(Unknown Source)
218
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
219
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
220
	at java.lang.Thread.run(Unknown Source)
221
Caused by: javax.smartcardio.CardException: transmitControlCommand() failed
222
	at sun.security.smartcardio.CardImpl.transmitControlCommand(Unknown Source)
223
	at org.openecard.scio.PCSCCard.transmitControlCommand(PCSCCard.java:107)
224
	... 5 common frames omitted
225
Caused by: sun.security.smartcardio.PCSCException: Unknown error 0x1
226
	at sun.security.smartcardio.PCSC.SCardControl(Native Method)
227
	... 7 common frames omitted
228
2019-09-28 18:06:30,967+02 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
229
2019-09-28 18:06:30,968+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
230
2019-09-28 18:06:30,968+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
231
2019-09-28 18:06:30,968+02 [IFD Watcher 0] DEBUG o.o.ifd.event.IfdEventRunner:213 - Found a terminal added event (Alcor Micro USB Smart Card Reader 0).
232
2019-09-28 18:06:30,968+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
233
2019-09-28 18:06:30,969+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.addon.EventHandler@ea6137.
234
2019-09-28 18:06:30,969+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
235
2019-09-28 18:06:30,969+02 [IFD Watcher 0] DEBUG o.o.ifd.event.IfdEventRunner:235 - Found a card insert event (Alcor Micro USB Smart Card Reader 0).
236
2019-09-28 18:06:30,969+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: TERMINAL_ADDED
237
2019-09-28 18:06:30,969+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=Alcor Micro USB Smart Card Reader 0, slot=null, ctx=8F27404E59BEC1306A299DCB3866A1D6
238
2019-09-28 18:06:30,970+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:394 - RecognitionInfo: null
239
2019-09-28 18:06:30,970+02 [IFD Watcher 0] INFO  o.o.ifd.event.IfdEventRunner:236 - Card with ATR=3BD818FF81B1FE451F038064041AB403810561 inserted.
240
2019-09-28 18:06:30,970+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
241
2019-09-28 18:06:30,970+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_INSERTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
242
2019-09-28 18:06:30,970+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_INSERTED to EventCallback org.openecard.addon.EventHandler@ea6137.
243
2019-09-28 18:06:30,970+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_INSERTED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
244
2019-09-28 18:06:30,970+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: CARD_INSERTED
245
2019-09-28 18:06:30,970+02 [IFD Watcher 0] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'Alcor Micro USB Smart Card Reader 0' is already connected.
246
2019-09-28 18:06:30,971+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=Alcor Micro USB Smart Card Reader 0, slot=null, ctx=8F27404E59BEC1306A299DCB3866A1D6
247
2019-09-28 18:06:30,971+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:392 - RecognitionInfo: http://bsi.bund.de/cif/unknown, 3BD818FF81B1FE451F038064041AB403810561
248
2019-09-28 18:06:30,971+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
249
2019-09-28 18:06:30,972+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:132 - Found ContextHandle in object of type Connect.
250
2019-09-28 18:06:30,979+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
251
2019-09-28 18:06:30,979+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
252
2019-09-28 18:06:30,979+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
253
2019-09-28 18:06:30,979+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Connect
254
2019-09-28 18:06:30,979+02 [IFD Watcher 0] DEBUG o.o.ifd.event.IfdEventRunner:213 - Found a terminal added event (DATEV Virtueller SmartCard Leser 0).
255
2019-09-28 18:06:30,979+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
256
2019-09-28 18:06:30,979+02 [IFD Watcher 1] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'Alcor Micro USB Smart Card Reader 0' is already connected.
257
2019-09-28 18:06:30,980+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.addon.EventHandler@ea6137.
258
2019-09-28 18:06:30,980+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
259
2019-09-28 18:06:30,986+02 [IFD Watcher 0] DEBUG o.o.ifd.event.IfdEventRunner:213 - Found a terminal added event (DATEV Virtueller SmartCard Replikator 0).
260
2019-09-28 18:06:30,987+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
261
2019-09-28 18:06:30,987+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.addon.EventHandler@ea6137.
262
2019-09-28 18:06:30,987+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
263
2019-09-28 18:06:30,991+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: TERMINAL_ADDED
264
2019-09-28 18:06:30,991+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
265
2019-09-28 18:06:30,992+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
266
2019-09-28 18:06:30,992+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=DATEV Virtueller SmartCard Leser 0, slot=null, ctx=8F27404E59BEC1306A299DCB3866A1D6
267
2019-09-28 18:06:30,992+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:394 - RecognitionInfo: null
268
2019-09-28 18:06:30,992+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
269
2019-09-28 18:06:30,992+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
270
2019-09-28 18:06:30,992+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: TERMINAL_ADDED
271
2019-09-28 18:06:30,992+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type BeginTransaction.
272
2019-09-28 18:06:30,993+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=DATEV Virtueller SmartCard Replikator 0, slot=null, ctx=8F27404E59BEC1306A299DCB3866A1D6
273
2019-09-28 18:06:30,993+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:394 - RecognitionInfo: null
274
2019-09-28 18:06:30,993+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
275
2019-09-28 18:06:30,994+02 [IFD Watcher 0] DEBUG o.o.ifd.event.IfdEventRunner:213 - Found a terminal added event (DATEV Virtueller SmartCard Replikator 1).
276
2019-09-28 18:06:30,994+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
277
2019-09-28 18:06:30,995+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.addon.EventHandler@ea6137.
278
2019-09-28 18:06:30,995+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
279
2019-09-28 18:06:30,995+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: TERMINAL_ADDED
280
2019-09-28 18:06:30,996+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=DATEV Virtueller SmartCard Replikator 1, slot=null, ctx=8F27404E59BEC1306A299DCB3866A1D6
281
2019-09-28 18:06:30,996+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:394 - RecognitionInfo: null
282
2019-09-28 18:06:30,996+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
283
2019-09-28 18:06:30,998+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
284
2019-09-28 18:06:30,998+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
285
2019-09-28 18:06:30,999+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
286
2019-09-28 18:06:30,999+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.BeginTransaction
287
2019-09-28 18:06:31,001+02 [IFD Watcher 0] DEBUG o.o.common.util.HandlerUtils:132 - Found ContextHandle in object of type GetIFDCapabilities.
288
2019-09-28 18:06:31,004+02 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
289
2019-09-28 18:06:31,005+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
290
2019-09-28 18:06:31,005+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
291
2019-09-28 18:06:31,005+02 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.GetIFDCapabilities
292
2019-09-28 18:06:31,005+02 [IFD Watcher 0] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'REINER SCT cyberJack RFID basis 1' is already connected.
293
2019-09-28 18:06:31,010+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
294
2019-09-28 18:06:31,010+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
295
2019-09-28 18:06:31,010+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
296
2019-09-28 18:06:31,011+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
297
2019-09-28 18:06:31,013+02 [IFD Watcher 0] WARN  o.o.ifd.scio.wrapper.TerminalInfo:323 - Unable to request features from reader.
298
org.openecard.common.ifd.scio.SCIOException: Failed to transmit control command to the terminal 'REINER SCT cyberJack RFID basis 1'.
299
	at org.openecard.scio.PCSCCard.transmitControlCommand(PCSCCard.java:110)
300
	at org.openecard.ifd.scio.wrapper.SingleThreadChannel.lambda$transmitControlCommand$2(SingleThreadChannel.java:288)
301
	at java.util.concurrent.FutureTask.run(Unknown Source)
302
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
303
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
304
	at java.lang.Thread.run(Unknown Source)
305
Caused by: javax.smartcardio.CardException: transmitControlCommand() failed
306
	at sun.security.smartcardio.CardImpl.transmitControlCommand(Unknown Source)
307
	at org.openecard.scio.PCSCCard.transmitControlCommand(PCSCCard.java:107)
308
	... 5 common frames omitted
309
Caused by: sun.security.smartcardio.PCSCException: Unknown error 0x32
310
	at sun.security.smartcardio.PCSC.SCardControl(Native Method)
311
	... 7 common frames omitted
312
2019-09-28 18:06:31,014+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
313
2019-09-28 18:06:31,014+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
314
2019-09-28 18:06:31,014+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
315
2019-09-28 18:06:31,015+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
316
2019-09-28 18:06:31,015+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
317
2019-09-28 18:06:31,018+02 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
318
2019-09-28 18:06:31,019+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
319
2019-09-28 18:06:31,019+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
320
2019-09-28 18:06:31,019+02 [IFD Watcher 0] DEBUG o.o.ifd.event.IfdEventRunner:213 - Found a terminal added event (REINER SCT cyberJack RFID basis 1).
321
2019-09-28 18:06:31,019+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
322
2019-09-28 18:06:31,019+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.addon.EventHandler@ea6137.
323
2019-09-28 18:06:31,019+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification TERMINAL_ADDED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
324
2019-09-28 18:06:31,019+02 [IFD Watcher 0] DEBUG o.o.ifd.event.IfdEventRunner:235 - Found a card insert event (REINER SCT cyberJack RFID basis 1).
325
2019-09-28 18:06:31,019+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: TERMINAL_ADDED
326
2019-09-28 18:06:31,020+02 [IFD Watcher 0] INFO  o.o.ifd.event.IfdEventRunner:236 - Card with ATR=3B8780018031B8738401E019 inserted.
327
2019-09-28 18:06:31,020+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_INSERTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
328
2019-09-28 18:06:31,020+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_INSERTED to EventCallback org.openecard.addon.EventHandler@ea6137.
329
2019-09-28 18:06:31,020+02 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_INSERTED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
330
2019-09-28 18:06:31,020+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=REINER SCT cyberJack RFID basis 1, slot=null, ctx=8F27404E59BEC1306A299DCB3866A1D6
331
2019-09-28 18:06:31,020+02 [IFD Watcher 0] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'REINER SCT cyberJack RFID basis 1' is already connected.
332
2019-09-28 18:06:31,020+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:394 - RecognitionInfo: null
333
2019-09-28 18:06:31,020+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
334
2019-09-28 18:06:31,020+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: CARD_INSERTED
335
2019-09-28 18:06:31,021+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=REINER SCT cyberJack RFID basis 1, slot=null, ctx=8F27404E59BEC1306A299DCB3866A1D6
336
2019-09-28 18:06:31,022+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:392 - RecognitionInfo: http://bsi.bund.de/cif/unknown, 3B8780018031B8738401E019
337
2019-09-28 18:06:31,022+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:132 - Found ContextHandle in object of type Connect.
338
2019-09-28 18:06:31,022+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
339
2019-09-28 18:06:31,025+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
340
2019-09-28 18:06:31,025+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
341
2019-09-28 18:06:31,026+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
342
2019-09-28 18:06:31,026+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Connect
343
2019-09-28 18:06:31,026+02 [IFD Watcher 2] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'REINER SCT cyberJack RFID basis 1' is already connected.
344
2019-09-28 18:06:31,041+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
345
2019-09-28 18:06:31,041+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
346
2019-09-28 18:06:31,041+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
347
2019-09-28 18:06:31,042+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type BeginTransaction.
348
2019-09-28 18:06:31,044+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
349
2019-09-28 18:06:31,044+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
350
2019-09-28 18:06:31,044+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
351
2019-09-28 18:06:31,044+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.BeginTransaction
352
2019-09-28 18:06:31,047+02 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:201 - Detecting initial terminal status.
353
2019-09-28 18:06:31,048+02 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:205 - Terminal='Alcor Micro USB Smart Card Reader 0' cardPresent=true
354
2019-09-28 18:06:31,048+02 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:205 - Terminal='DATEV Virtueller SmartCard Leser 0' cardPresent=false
355
2019-09-28 18:06:31,049+02 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:205 - Terminal='DATEV Virtueller SmartCard Replikator 0' cardPresent=false
356
2019-09-28 18:06:31,050+02 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:205 - Terminal='DATEV Virtueller SmartCard Replikator 1' cardPresent=false
357
2019-09-28 18:06:31,050+02 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:205 - Terminal='REINER SCT cyberJack RFID basis 1' cardPresent=true
358
2019-09-28 18:06:31,053+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
359
2019-09-28 18:06:31,054+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
360
2019-09-28 18:06:31,054+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
361
2019-09-28 18:06:31,054+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
362
2019-09-28 18:06:31,057+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
363
2019-09-28 18:06:31,057+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
364
2019-09-28 18:06:31,057+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
365
2019-09-28 18:06:31,057+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
366
2019-09-28 18:06:31,058+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
367
2019-09-28 18:06:31,085+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
368
2019-09-28 18:06:31,090+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
369
2019-09-28 18:06:31,091+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
370
2019-09-28 18:06:31,091+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
371
2019-09-28 18:06:31,091+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
372
2019-09-28 18:06:31,092+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
373
2019-09-28 18:06:31,094+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
374
2019-09-28 18:06:31,094+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
375
2019-09-28 18:06:31,094+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
376
2019-09-28 18:06:31,094+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
377
2019-09-28 18:06:31,095+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C020003
378
2019-09-28 18:06:31,098+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
379
2019-09-28 18:06:31,098+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
380
2019-09-28 18:06:31,098+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
381
2019-09-28 18:06:31,098+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
382
2019-09-28 18:06:31,101+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
383
2019-09-28 18:06:31,101+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
384
2019-09-28 18:06:31,101+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
385
2019-09-28 18:06:31,101+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
386
2019-09-28 18:06:31,101+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C020003
387
2019-09-28 18:06:31,102+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6A82
388
2019-09-28 18:06:31,108+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6A82
389
2019-09-28 18:06:31,108+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
390
2019-09-28 18:06:31,109+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
391
2019-09-28 18:06:31,109+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
392
2019-09-28 18:06:31,109+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
393
2019-09-28 18:06:31,112+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
394
2019-09-28 18:06:31,113+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
395
2019-09-28 18:06:31,113+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
396
2019-09-28 18:06:31,113+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
397
2019-09-28 18:06:31,113+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
398
2019-09-28 18:06:31,114+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
399
2019-09-28 18:06:31,114+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
400
2019-09-28 18:06:31,115+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
401
2019-09-28 18:06:31,115+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
402
2019-09-28 18:06:31,117+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
403
2019-09-28 18:06:31,117+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
404
2019-09-28 18:06:31,118+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
405
2019-09-28 18:06:31,118+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
406
2019-09-28 18:06:31,118+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
407
2019-09-28 18:06:31,125+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
408
2019-09-28 18:06:31,125+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
409
2019-09-28 18:06:31,137+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
410
2019-09-28 18:06:31,137+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
411
2019-09-28 18:06:31,138+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
412
2019-09-28 18:06:31,138+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
413
2019-09-28 18:06:31,139+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
414
2019-09-28 18:06:31,139+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
415
2019-09-28 18:06:31,139+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
416
2019-09-28 18:06:31,139+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
417
2019-09-28 18:06:31,141+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
418
2019-09-28 18:06:31,141+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
419
2019-09-28 18:06:31,141+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
420
2019-09-28 18:06:31,141+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
421
2019-09-28 18:06:31,142+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C022F00
422
2019-09-28 18:06:31,142+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
423
2019-09-28 18:06:31,142+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
424
2019-09-28 18:06:31,143+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
425
2019-09-28 18:06:31,143+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
426
2019-09-28 18:06:31,143+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C022F00
427
2019-09-28 18:06:31,152+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
428
2019-09-28 18:06:31,159+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
429
2019-09-28 18:06:31,162+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
430
2019-09-28 18:06:31,163+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
431
2019-09-28 18:06:31,163+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
432
2019-09-28 18:06:31,164+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
433
2019-09-28 18:06:31,168+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
434
2019-09-28 18:06:31,168+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
435
2019-09-28 18:06:31,169+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
436
2019-09-28 18:06:31,169+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
437
2019-09-28 18:06:31,170+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00B20404FF
438
2019-09-28 18:06:31,171+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
439
2019-09-28 18:06:31,171+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
440
2019-09-28 18:06:31,171+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
441
2019-09-28 18:06:31,172+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
442
2019-09-28 18:06:31,174+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
443
2019-09-28 18:06:31,175+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
444
2019-09-28 18:06:31,175+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
445
2019-09-28 18:06:31,175+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
446
2019-09-28 18:06:31,176+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00B20404FF
447
2019-09-28 18:06:31,176+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6D00
448
2019-09-28 18:06:31,185+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
449
2019-09-28 18:06:31,185+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
450
2019-09-28 18:06:31,185+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
451
2019-09-28 18:06:31,185+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
452
2019-09-28 18:06:31,188+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
453
2019-09-28 18:06:31,188+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
454
2019-09-28 18:06:31,188+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
455
2019-09-28 18:06:31,188+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
456
2019-09-28 18:06:31,188+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
457
2019-09-28 18:06:31,196+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 610E4F0CA000000244465F43657274736282
458
2019-09-28 18:06:31,196+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
459
2019-09-28 18:06:31,206+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
460
2019-09-28 18:06:31,207+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
461
2019-09-28 18:06:31,207+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
462
2019-09-28 18:06:31,209+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
463
2019-09-28 18:06:31,209+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
464
2019-09-28 18:06:31,209+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
465
2019-09-28 18:06:31,210+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
466
2019-09-28 18:06:31,212+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
467
2019-09-28 18:06:31,213+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
468
2019-09-28 18:06:31,213+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
469
2019-09-28 18:06:31,214+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
470
2019-09-28 18:06:31,214+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
471
2019-09-28 18:06:31,214+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C022F00
472
2019-09-28 18:06:31,215+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
473
2019-09-28 18:06:31,215+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
474
2019-09-28 18:06:31,216+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
475
2019-09-28 18:06:31,216+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
476
2019-09-28 18:06:31,217+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
477
2019-09-28 18:06:31,223+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
478
2019-09-28 18:06:31,228+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
479
2019-09-28 18:06:31,228+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
480
2019-09-28 18:06:31,228+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
481
2019-09-28 18:06:31,228+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
482
2019-09-28 18:06:31,228+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
483
2019-09-28 18:06:31,231+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
484
2019-09-28 18:06:31,232+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
485
2019-09-28 18:06:31,232+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
486
2019-09-28 18:06:31,232+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
487
2019-09-28 18:06:31,233+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00B20304FF
488
2019-09-28 18:06:31,233+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
489
2019-09-28 18:06:31,233+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
490
2019-09-28 18:06:31,233+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
491
2019-09-28 18:06:31,233+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
492
2019-09-28 18:06:31,235+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
493
2019-09-28 18:06:31,235+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
494
2019-09-28 18:06:31,235+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
495
2019-09-28 18:06:31,235+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
496
2019-09-28 18:06:31,236+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C022F00
497
2019-09-28 18:06:31,238+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6D00
498
2019-09-28 18:06:31,241+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
499
2019-09-28 18:06:31,241+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
500
2019-09-28 18:06:31,242+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
501
2019-09-28 18:06:31,242+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
502
2019-09-28 18:06:31,243+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
503
2019-09-28 18:06:31,243+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
504
2019-09-28 18:06:31,243+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
505
2019-09-28 18:06:31,244+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
506
2019-09-28 18:06:31,244+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4040C0FF04573744549442076657220312E30
507
2019-09-28 18:06:31,252+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
508
2019-09-28 18:06:31,256+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
509
2019-09-28 18:06:31,256+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
510
2019-09-28 18:06:31,256+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
511
2019-09-28 18:06:31,256+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
512
2019-09-28 18:06:31,256+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6A82
513
2019-09-28 18:06:31,261+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
514
2019-09-28 18:06:31,262+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
515
2019-09-28 18:06:31,262+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
516
2019-09-28 18:06:31,262+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
517
2019-09-28 18:06:31,262+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00B20304FF
518
2019-09-28 18:06:31,264+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
519
2019-09-28 18:06:31,264+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
520
2019-09-28 18:06:31,264+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
521
2019-09-28 18:06:31,264+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
522
2019-09-28 18:06:31,265+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
523
2019-09-28 18:06:31,266+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
524
2019-09-28 18:06:31,266+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
525
2019-09-28 18:06:31,266+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
526
2019-09-28 18:06:31,266+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4040C0FD23300000045737445494420763335
527
2019-09-28 18:06:31,276+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6A82
528
2019-09-28 18:06:31,279+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
529
2019-09-28 18:06:31,279+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
530
2019-09-28 18:06:31,279+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
531
2019-09-28 18:06:31,280+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
532
2019-09-28 18:06:31,281+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 610E4F0CA000000063504B43532D31356282
533
2019-09-28 18:06:31,282+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
534
2019-09-28 18:06:31,282+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
535
2019-09-28 18:06:31,282+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
536
2019-09-28 18:06:31,283+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
537
2019-09-28 18:06:31,283+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
538
2019-09-28 18:06:31,285+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
539
2019-09-28 18:06:31,285+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
540
2019-09-28 18:06:31,286+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
541
2019-09-28 18:06:31,286+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
542
2019-09-28 18:06:31,288+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
543
2019-09-28 18:06:31,288+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
544
2019-09-28 18:06:31,289+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
545
2019-09-28 18:06:31,289+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
546
2019-09-28 18:06:31,289+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4040C0FF04573744549442076657220312E30
547
2019-09-28 18:06:31,292+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
548
2019-09-28 18:06:31,297+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
549
2019-09-28 18:06:31,297+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
550
2019-09-28 18:06:31,297+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
551
2019-09-28 18:06:31,297+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
552
2019-09-28 18:06:31,299+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
553
2019-09-28 18:06:31,299+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
554
2019-09-28 18:06:31,300+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
555
2019-09-28 18:06:31,300+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
556
2019-09-28 18:06:31,300+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C022F00
557
2019-09-28 18:06:31,309+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
558
2019-09-28 18:06:31,310+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6A82
559
2019-09-28 18:06:31,313+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
560
2019-09-28 18:06:31,313+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
561
2019-09-28 18:06:31,314+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
562
2019-09-28 18:06:31,314+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
563
2019-09-28 18:06:31,315+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
564
2019-09-28 18:06:31,315+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
565
2019-09-28 18:06:31,315+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
566
2019-09-28 18:06:31,315+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
567
2019-09-28 18:06:31,316+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
568
2019-09-28 18:06:31,316+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
569
2019-09-28 18:06:31,316+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
570
2019-09-28 18:06:31,317+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
571
2019-09-28 18:06:31,317+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00B00000FF
572
2019-09-28 18:06:31,318+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
573
2019-09-28 18:06:31,318+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
574
2019-09-28 18:06:31,318+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
575
2019-09-28 18:06:31,318+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
576
2019-09-28 18:06:31,318+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4040C0FD23300000045737445494420763335
577
2019-09-28 18:06:31,329+02 [IFD Watcher 2] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 61324F0FE828BD080FA000000167455349474E500F434941207A752044462E655369676E5100730C4F0AA000000167455349474E61094F07A0000002471001610B4F09E80704007F00070302610C4F0AA000000167455349474E6282
578
2019-09-28 18:06:31,332+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
579
2019-09-28 18:06:31,333+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
580
2019-09-28 18:06:31,333+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
581
2019-09-28 18:06:31,333+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type EndTransaction.
582
2019-09-28 18:06:31,334+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
583
2019-09-28 18:06:31,334+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
584
2019-09-28 18:06:31,335+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
585
2019-09-28 18:06:31,335+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.EndTransaction
586
2019-09-28 18:06:31,339+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
587
2019-09-28 18:06:31,339+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
588
2019-09-28 18:06:31,339+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
589
2019-09-28 18:06:31,339+02 [IFD Watcher 2] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Disconnect.
590
2019-09-28 18:06:31,340+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6A82
591
2019-09-28 18:06:31,341+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
592
2019-09-28 18:06:31,341+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
593
2019-09-28 18:06:31,341+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
594
2019-09-28 18:06:31,341+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Disconnect
595
2019-09-28 18:06:31,345+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
596
2019-09-28 18:06:31,346+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
597
2019-09-28 18:06:31,346+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
598
2019-09-28 18:06:31,346+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
599
2019-09-28 18:06:31,347+02 [IFD Watcher 2] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
600
2019-09-28 18:06:31,347+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
601
2019-09-28 18:06:31,347+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
602
2019-09-28 18:06:31,347+02 [IFD Watcher 2] DEBUG org.openecard.ifd.event.Recognizer:60 - Found a recognized card event (REINER SCT cyberJack RFID basis 1).
603
2019-09-28 18:06:31,347+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_RECOGNIZED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
604
2019-09-28 18:06:31,347+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_RECOGNIZED to EventCallback org.openecard.addon.EventHandler@ea6137.
605
2019-09-28 18:06:31,347+02 [IFD Watcher 2] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_RECOGNIZED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
606
2019-09-28 18:06:31,348+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: CARD_RECOGNIZED
607
2019-09-28 18:06:31,348+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
608
2019-09-28 18:06:31,348+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
609
2019-09-28 18:06:31,348+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
610
2019-09-28 18:06:31,348+02 [Dispatcher Event 0] INFO  o.o.c.sal.state.SALStateCallback:63 - Add ConnectionHandle to SAL:
611
ConnectionHandle:
612
  Session: C-AaenRmJCtZKKUzQvzqkw
613
  ContextHandle: 8F27404E59BEC1306A299DCB3866A1D6
614
  IFDName: REINER SCT cyberJack RFID basis 1  SlotIndex: 0
615
  CardType: http://bsi.bund.de/cif/npa.xml
616
2019-09-28 18:06:31,349+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
617
2019-09-28 18:06:31,349+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=REINER SCT cyberJack RFID basis 1, slot=null, ctx=8F27404E59BEC1306A299DCB3866A1D6
618
2019-09-28 18:06:31,349+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:392 - RecognitionInfo: http://bsi.bund.de/cif/npa.xml, null
619
2019-09-28 18:06:31,349+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
620
2019-09-28 18:06:31,349+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
621
2019-09-28 18:06:31,349+02 [Dispatcher Event 0] DEBUG org.openecard.sal.SelectorSAL:185 - Looking up responsible SAL for handle with, ctx=8F27404E59BEC1306A299DCB3866A1D6, slot=null
622
2019-09-28 18:06:31,349+02 [Dispatcher Event 0] DEBUG org.openecard.sal.SelectorSAL:193 - Requesting CIF from CIF-Repo for type=http://bsi.bund.de/cif/npa.xml.
623
2019-09-28 18:06:31,349+02 [Dispatcher Event 0] DEBUG o.o.r.staticrepo.LocalCifRepo:131 - Requesting CIFs with GetCardInfoOrACD call.
624
2019-09-28 18:06:31,367+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
625
2019-09-28 18:06:31,371+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
626
2019-09-28 18:06:31,371+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
627
2019-09-28 18:06:31,371+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
628
2019-09-28 18:06:31,371+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
629
2019-09-28 18:06:31,373+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
630
2019-09-28 18:06:31,373+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
631
2019-09-28 18:06:31,373+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
632
2019-09-28 18:06:31,376+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
633
2019-09-28 18:06:31,376+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C022F00
634
2019-09-28 18:06:31,384+02 [Dispatcher Event 2] DEBUG org.openecard.sal.SelectorSAL:205 - Requesting CIF from CIF-Repo for type=http://bsi.bund.de/cif/npa.xml.
635
2019-09-28 18:06:31,384+02 [Dispatcher Event 2] DEBUG o.o.r.staticrepo.LocalCifRepo:131 - Requesting CIFs with GetCardInfoOrACD call.
636
2019-09-28 18:06:31,394+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
637
2019-09-28 18:06:31,398+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
638
2019-09-28 18:06:31,398+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
639
2019-09-28 18:06:31,398+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
640
2019-09-28 18:06:31,399+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
641
2019-09-28 18:06:31,400+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
642
2019-09-28 18:06:31,400+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
643
2019-09-28 18:06:31,400+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
644
2019-09-28 18:06:31,400+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
645
2019-09-28 18:06:31,401+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00B00000FF
646
2019-09-28 18:06:31,401+02 [Dispatcher Event 0] DEBUG o.o.r.staticrepo.LocalCifRepo:172 - Returning CIFs from GetCardInfoOrACD call.
647
2019-09-28 18:06:31,403+02 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:94 - Add new entry to card states: CardStateEntry@0 {
648
  handle=  ConnectionHandle {
649
    ctx=8F27404E59BEC1306A299DCB3866A1D6
650
    ifd=REINER SCT cyberJack RFID basis 1
651
    idx=0
652
    slot=null
653
    app=3F00
654
    Recognition {
655
      typ=http://bsi.bund.de/cif/npa.xml
656
      ident=null
657
    }
658
  }
659
}
660
2019-09-28 18:06:31,404+02 [Dispatcher Event 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification RECOGNIZED_CARD_ACTIVE to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
661
2019-09-28 18:06:31,404+02 [Dispatcher Event 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification RECOGNIZED_CARD_ACTIVE to EventCallback org.openecard.addon.EventHandler@ea6137.
662
2019-09-28 18:06:31,415+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6981
663
2019-09-28 18:06:31,417+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
664
2019-09-28 18:06:31,417+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
665
2019-09-28 18:06:31,417+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
666
2019-09-28 18:06:31,418+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
667
2019-09-28 18:06:31,419+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
668
2019-09-28 18:06:31,419+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
669
2019-09-28 18:06:31,419+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
670
2019-09-28 18:06:31,419+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
671
2019-09-28 18:06:31,420+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
672
2019-09-28 18:06:31,421+02 [Dispatcher Event 2] DEBUG o.o.r.staticrepo.LocalCifRepo:172 - Returning CIFs from GetCardInfoOrACD call.
673
2019-09-28 18:06:31,430+02 [Update-Task] WARN  o.o.common.util.VersionUpdateLoader:105 - Package type win32 not supported in update list.
674
2019-09-28 18:06:31,431+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
675
2019-09-28 18:06:31,433+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
676
2019-09-28 18:06:31,434+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
677
2019-09-28 18:06:31,434+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
678
2019-09-28 18:06:31,434+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
679
2019-09-28 18:06:31,435+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
680
2019-09-28 18:06:31,435+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
681
2019-09-28 18:06:31,435+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
682
2019-09-28 18:06:31,435+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
683
2019-09-28 18:06:31,435+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4010C025015
684
2019-09-28 18:06:31,452+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
685
2019-09-28 18:06:31,455+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
686
2019-09-28 18:06:31,456+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
687
2019-09-28 18:06:31,456+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
688
2019-09-28 18:06:31,456+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
689
2019-09-28 18:06:31,457+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
690
2019-09-28 18:06:31,457+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
691
2019-09-28 18:06:31,457+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
692
2019-09-28 18:06:31,457+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
693
2019-09-28 18:06:31,458+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C025032
694
2019-09-28 18:06:31,472+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
695
2019-09-28 18:06:31,475+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
696
2019-09-28 18:06:31,475+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
697
2019-09-28 18:06:31,475+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
698
2019-09-28 18:06:31,475+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
699
2019-09-28 18:06:31,476+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
700
2019-09-28 18:06:31,476+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
701
2019-09-28 18:06:31,477+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
702
2019-09-28 18:06:31,477+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
703
2019-09-28 18:06:31,477+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00B00000FF
704
2019-09-28 18:06:31,498+02 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 303B02010004000C10442D545255535420476D624820284329801E442D545255535420436172642056332E30207374616E6461726420326765030204506282
705
2019-09-28 18:06:31,502+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
706
2019-09-28 18:06:31,502+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
707
2019-09-28 18:06:31,502+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
708
2019-09-28 18:06:31,502+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type EndTransaction.
709
2019-09-28 18:06:31,504+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
710
2019-09-28 18:06:31,505+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
711
2019-09-28 18:06:31,505+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
712
2019-09-28 18:06:31,505+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.EndTransaction
713
2019-09-28 18:06:31,508+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
714
2019-09-28 18:06:31,508+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
715
2019-09-28 18:06:31,509+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
716
2019-09-28 18:06:31,509+02 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Disconnect.
717
2019-09-28 18:06:31,511+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
718
2019-09-28 18:06:31,511+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
719
2019-09-28 18:06:31,511+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
720
2019-09-28 18:06:31,511+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Disconnect
721
2019-09-28 18:06:31,514+02 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
722
2019-09-28 18:06:31,514+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
723
2019-09-28 18:06:31,514+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
724
2019-09-28 18:06:31,514+02 [IFD Watcher 1] DEBUG org.openecard.ifd.event.Recognizer:60 - Found a recognized card event (Alcor Micro USB Smart Card Reader 0).
725
2019-09-28 18:06:31,514+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_RECOGNIZED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
726
2019-09-28 18:06:31,514+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_RECOGNIZED to EventCallback org.openecard.addon.EventHandler@ea6137.
727
2019-09-28 18:06:31,514+02 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_RECOGNIZED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
728
2019-09-28 18:06:31,514+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: CARD_RECOGNIZED
729
2019-09-28 18:06:31,515+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=Alcor Micro USB Smart Card Reader 0, slot=null, ctx=8F27404E59BEC1306A299DCB3866A1D6
730
2019-09-28 18:06:31,515+02 [Dispatcher Event 0] INFO  o.o.c.sal.state.SALStateCallback:63 - Add ConnectionHandle to SAL:
731
ConnectionHandle:
732
  Session: C-AaenRmJCtZKKUzQvzqkw
733
  ContextHandle: 8F27404E59BEC1306A299DCB3866A1D6
734
  IFDName: Alcor Micro USB Smart Card Reader 0  SlotIndex: 0
735
  CardType: http://www.ihk.de/cif
736
2019-09-28 18:06:31,515+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:392 - RecognitionInfo: http://www.ihk.de/cif, null
737
2019-09-28 18:06:31,515+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
738
2019-09-28 18:06:31,515+02 [Dispatcher Event 0] DEBUG org.openecard.sal.SelectorSAL:185 - Looking up responsible SAL for handle with, ctx=8F27404E59BEC1306A299DCB3866A1D6, slot=null
739
2019-09-28 18:06:31,515+02 [Dispatcher Event 0] DEBUG org.openecard.sal.SelectorSAL:193 - Requesting CIF from CIF-Repo for type=http://www.ihk.de/cif.
740
2019-09-28 18:06:31,515+02 [Dispatcher Event 0] DEBUG o.o.r.staticrepo.LocalCifRepo:131 - Requesting CIFs with GetCardInfoOrACD call.
741
2019-09-28 18:06:31,535+02 [Dispatcher Event 0] DEBUG o.o.r.staticrepo.LocalCifRepo:172 - Returning CIFs from GetCardInfoOrACD call.
742
2019-09-28 18:06:31,536+02 [Dispatcher Event 2] DEBUG org.openecard.sal.SelectorSAL:205 - Requesting CIF from CIF-Repo for type=http://www.ihk.de/cif.
743
2019-09-28 18:06:31,535+02 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:94 - Add new entry to card states: CardStateEntry@1 {
744
  handle=  ConnectionHandle {
745
    ctx=8F27404E59BEC1306A299DCB3866A1D6
746
    ifd=Alcor Micro USB Smart Card Reader 0
747
    idx=0
748
    slot=null
749
    app=D2760001448000
750
    Recognition {
751
      typ=http://www.ihk.de/cif
752
      ident=null
753
    }
754
  }
755
}
756
2019-09-28 18:06:31,536+02 [Dispatcher Event 2] DEBUG o.o.r.staticrepo.LocalCifRepo:131 - Requesting CIFs with GetCardInfoOrACD call.
757
2019-09-28 18:06:31,536+02 [Dispatcher Event 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification RECOGNIZED_CARD_ACTIVE to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
758
2019-09-28 18:06:31,536+02 [Dispatcher Event 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification RECOGNIZED_CARD_ACTIVE to EventCallback org.openecard.addon.EventHandler@ea6137.
759
2019-09-28 18:06:31,552+02 [Dispatcher Event 2] DEBUG o.o.r.staticrepo.LocalCifRepo:172 - Returning CIFs from GetCardInfoOrACD call.
760
2019-09-28 18:06:50,000+02 [Thread-9] DEBUG o.o.c.b.h.h.HttpAppPluginActionHandler:88 - HTTP request: GET /eID-Client?tcTokenURL=https%3A%2F%2Fde-mw.eid.digst.dk%2Feidas-middleware%2FTcToken%3FsessionID%3D_14cc4789-89b7-56a2-110f-2bd591933b21 [Host: 127.0.0.1:24727, Connection: keep-alive, Upgrade-Insecure-Requests: 1, User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.90 Safari/537.36, Sec-Fetch-Mode: navigate, Sec-Fetch-User: ?1, Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3, Sec-Fetch-Site: cross-site, Accept-Encoding: gzip, deflate, br, Accept-Language: en-US,en;q=0.9,de-DE;q=0.8,de;q=0.7]
761
2019-09-28 18:06:50,012+02 [Thread-9] WARN  org.openecard.common.I18n:152 - Failed to load resource tr03112 for lang de_DE.
762
2019-09-28 18:06:50,017+02 [Thread-9] WARN  org.openecard.common.I18n:152 - Failed to load resource tctoken for lang de_DE.
763
2019-09-28 18:06:50,021+02 [Thread-9] WARN  org.openecard.common.I18n:152 - Failed to load resource pinplugin for lang de_DE.
764
2019-09-28 18:06:50,023+02 [Thread-9] WARN  org.openecard.common.I18n:152 - Failed to load resource pace for lang de_DE.
765
2019-09-28 18:06:50,026+02 [FuturePromise-3] WARN  o.o.binding.tctoken.TCTokenHandler:156 - Schema validation is disabled.
766
2019-09-28 18:06:50,040+02 [Thread-9] DEBUG org.openecard.sal.SelectorSAL:205 - Requesting CIF from CIF-Repo for type=http://bsi.bund.de/cif/npa.xml.
767
2019-09-28 18:06:50,040+02 [Thread-9] DEBUG o.o.r.staticrepo.LocalCifRepo:131 - Requesting CIFs with GetCardInfoOrACD call.
768
2019-09-28 18:06:50,062+02 [Thread-9] DEBUG o.o.r.staticrepo.LocalCifRepo:172 - Returning CIFs from GetCardInfoOrACD call.
769
2019-09-28 18:06:50,067+02 [Thread-9] INFO  o.o.binding.tctoken.ResourceContext:207 - Trying to load resource from: https://de-mw.eid.digst.dk/eidas-middleware/TcToken?sessionID=_14cc4789-89b7-56a2-110f-2bd591933b21
770
2019-09-28 18:06:50,106+02 [Thread-9] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for java. Trying next one.
771
2019-09-28 18:06:50,119+02 [Thread-9] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for IE. Trying next one.
772
2019-09-28 18:06:50,122+02 [Thread-9] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for desktop. Trying next one.
773
2019-09-28 18:06:50,123+02 [Thread-9] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for env. Trying next one.
774
2019-09-28 18:06:50,124+02 [Thread-9] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for java. Trying next one.
775
2019-09-28 18:06:50,126+02 [Thread-9] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for IE. Trying next one.
776
2019-09-28 18:06:50,128+02 [Thread-9] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for desktop. Trying next one.
777
2019-09-28 18:06:50,128+02 [Thread-9] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for env. Trying next one.
778
2019-09-28 18:06:50,128+02 [Thread-9] DEBUG o.o.crypto.tls.proxy.ProxySettings:133 - Selecting proxy: DIRECT
779
2019-09-28 18:06:50,128+02 [Thread-9] DEBUG o.o.crypto.tls.proxy.ProxySettings:168 - Using proxy (DIRECT) to obtain socket.
780
2019-09-28 18:06:50,220+02 [Thread-9] DEBUG o.o.binding.tctoken.ResourceContext:244 - Performing TLS handshake.
781
2019-09-28 18:06:50,354+02 [Thread-9] DEBUG o.o.c.tls.verify.HostnameVerifier:126 - Comparing connection hostname against certificate hostname: [de-mw.eid.digst.dk] [de-mw.eid.digst.dk]
782
2019-09-28 18:06:50,513+02 [Thread-9] DEBUG o.o.binding.tctoken.ResourceContext:246 - TLS handshake performed.
783
2019-09-28 18:06:50,534+02 [Thread-9] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request:
784
  GET /eidas-middleware/TcToken?sessionID=_14cc4789-89b7-56a2-110f-2bd591933b21 HTTP/1.1
785
  Connection: keep-alive
786
  User-Agent: Open eCard App/1.3.0
787
  Host: de-mw.eid.digst.dk
788
  Accept: text/xml, */*;q=0.8
789
  Accept-Charset: utf-8, *;q=0.8
790

    
791
2019-09-28 18:06:50,534+02 [Thread-9] DEBUG o.o.binding.tctoken.ResourceContext:267 - Sending HTTP request.
792
2019-09-28 18:06:50,604+02 [Thread-9] DEBUG o.o.binding.tctoken.ResourceContext:270 - HTTP response received.
793
2019-09-28 18:06:50,605+02 [Thread-9] DEBUG o.o.transport.httpcore.HttpUtils:112 - HTTP Response:
794
  HTTP/1.1 200 
795
  X-Content-Type-Options: nosniff
796
  X-XSS-Protection: 1; mode=block
797
  Cache-Control: no-cache, no-store, max-age=0, must-revalidate
798
  Pragma: no-cache
799
  Expires: 0
800
  Strict-Transport-Security: max-age=31536000 ; includeSubDomains
801
  X-Frame-Options: DENY
802
  Content-Type: text/xml;charset=utf-8
803
  Content-Length: 380
804
  Date: Sat, 28 Sep 2019 16:06:50 GMT
805

    
806

    
807
2019-09-28 18:06:50,607+02 [Thread-9] DEBUG o.o.binding.tctoken.TCTokenContext:90 - Received TCToken:
808
<TCTokenType>
809
<ServerAddress>https://de-mw.eid.digst.dk:443/eidas-middleware/paosreceiver</ServerAddress>
810
<SessionIdentifier>2e9ff28c-ef9c-45f9-8c39-15c68b416d68</SessionIdentifier>
811
<RefreshAddress>https://de-mw.eid.digst.dk/eidas-middleware/ResponseSender?refID=460f2db4-cf73-4338-800a-ba53c82059da</RefreshAddress>
812
<Binding>urn:liberty:paos:2006-08</Binding>
813
</TCTokenType>
814
2019-09-28 18:06:50,608+02 [Thread-9] DEBUG o.o.binding.tctoken.TCTokenContext:92 - Cleaned up TCToken:
815
<TCTokenType>
816
<ServerAddress>https://de-mw.eid.digst.dk:443/eidas-middleware/paosreceiver</ServerAddress>
817
<SessionIdentifier>2e9ff28c-ef9c-45f9-8c39-15c68b416d68</SessionIdentifier>
818
<RefreshAddress>https://de-mw.eid.digst.dk/eidas-middleware/ResponseSender?refID=460f2db4-cf73-4338-800a-ba53c82059da</RefreshAddress>
819
<Binding>urn:liberty:paos:2006-08</Binding>
820
</TCTokenType>
821
2019-09-28 18:06:50,614+02 [Thread-9] DEBUG o.o.common.util.TR03112Utils:61 - Checking SOP for https://de-mw.eid.digst.dk:443/eidas-middleware/paosreceiver and https://de-mw.eid.digst.dk/eidas-middleware/TcToken?sessionID=_14cc4789-89b7-56a2-110f-2bd591933b21.
822
2019-09-28 18:06:50,622+02 [Thread-9] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
823
2019-09-28 18:06:50,622+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
824
2019-09-28 18:06:50,623+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
825
2019-09-28 18:06:50,623+02 [Thread-9] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.CardApplicationPath
826
2019-09-28 18:06:50,627+02 [Thread-9] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
827
2019-09-28 18:06:50,627+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
828
2019-09-28 18:06:50,627+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
829
2019-09-28 18:06:50,629+02 [Thread-9] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
830
2019-09-28 18:06:50,629+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
831
2019-09-28 18:06:50,629+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
832
2019-09-28 18:06:50,629+02 [Thread-9] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.CardApplicationConnect
833
2019-09-28 18:06:50,630+02 [Thread-9] DEBUG o.o.common.util.HandlerUtils:132 - Found ContextHandle in object of type Connect.
834
2019-09-28 18:06:50,631+02 [Thread-9] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
835
2019-09-28 18:06:50,632+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
836
2019-09-28 18:06:50,632+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
837
2019-09-28 18:06:50,632+02 [Thread-9] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Connect
838
2019-09-28 18:06:50,632+02 [Thread-9] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'REINER SCT cyberJack RFID basis 1' is already connected.
839
2019-09-28 18:06:50,638+02 [Thread-9] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
840
2019-09-28 18:06:50,639+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
841
2019-09-28 18:06:50,639+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
842
2019-09-28 18:06:50,640+02 [Thread-9] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
843
2019-09-28 18:06:50,641+02 [Thread-9] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
844
2019-09-28 18:06:50,642+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
845
2019-09-28 18:06:50,642+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
846
2019-09-28 18:06:50,642+02 [Thread-9] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
847
2019-09-28 18:06:50,642+02 [Thread-9] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
848
2019-09-28 18:06:50,651+02 [Thread-9] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
849
2019-09-28 18:06:50,655+02 [Thread-9] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
850
2019-09-28 18:06:50,655+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
851
2019-09-28 18:06:50,655+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
852
2019-09-28 18:06:50,656+02 [Thread-9] DEBUG o.o.common.sal.state.CardStateMap:94 - Add new entry to card states: CardStateEntry@2 {
853
  handle=  ConnectionHandle {
854
    ctx=8F27404E59BEC1306A299DCB3866A1D6
855
    ifd=REINER SCT cyberJack RFID basis 1
856
    idx=0
857
    slot=CA04CD35965315933C47FAA7680FDA7F1CA49F109E698B57
858
    app=3F00
859
    Recognition {
860
      typ=http://bsi.bund.de/cif/npa.xml
861
      ident=null
862
    }
863
  }
864
}
865
2019-09-28 18:06:50,659+02 [Thread-9] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
866
2019-09-28 18:06:50,659+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
867
2019-09-28 18:06:50,659+02 [Thread-9] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
868
2019-09-28 18:06:50,668+02 [PAOS] DEBUG org.openecard.transport.paos.PAOS:470 - Opening connection to PAOS server.
869
2019-09-28 18:06:50,668+02 [PAOS] DEBUG org.openecard.transport.paos.PAOS:473 - Connection to PAOS server established.
870
2019-09-28 18:06:50,669+02 [PAOS] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request (before adding content):
871
  POST /eidas-middleware/paosreceiver HTTP/1.1
872
  Connection: keep-alive
873
  User-Agent: Open eCard App/1.3.0
874
  Host: de-mw.eid.digst.dk:443
875
  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:Hash";"urn:iso:std:iso-iec:24727:tech:schema:Encipher";"urn:iso:std:iso-iec:24727:tech:schema:DSIList";"urn:iso:std:iso-iec:24727:tech:schema:DSIRead";"urn:iso:std:iso-iec:24727:tech:schema:DSIWrite";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationServiceList";"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:VerifySignature";"urn:iso:std:iso-iec:24727:tech:schema:GetRandom";"urn:iso:std:iso-iec:24727:tech:schema:DIDAuthenticate";"urn:iso:std:iso-iec:24727:tech:schema:DataSetSelect";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationList";"urn:iso:std:iso-iec:24727:tech:schema:VerifyCertificate";"urn:iso:std:iso-iec:24727:tech:schema:DataSetList";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationServiceDescribe";"urn:iso:std:iso-iec:24727:tech:schema:Sign";"urn:iso:std:iso-iec:24727:tech:schema:DIDGet";"urn:iso:std:iso-iec:24727:tech:schema:DIDList";"urn:iso:std:iso-iec:24727:tech:schema:ACLList";"urn:iso:std:iso-iec:24727:tech:schema:Decipher"
876
  Accept: text/xml, application/xml, application/vnd.paos+xml
877

    
878
2019-09-28 18:06:50,697+02 [PAOS] DEBUG org.openecard.transport.paos.PAOS:268 - Message sent:
879
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
880
<Envelope xmlns="http://schemas.xmlsoap.org/soap/envelope/">
881
  <Header>
882
    <PAOS xmlns:ns0="http://schemas.xmlsoap.org/soap/envelope/" ns0:actor="http://schemas.xmlsoap.org/soap/actor/next" xmlns:ns1="http://schemas.xmlsoap.org/soap/envelope/" ns1:mustUnderstand="1" xmlns="urn:liberty:paos:2006-08">
883
      <Version>urn:liberty:paos:2006-08</Version>
884
      <EndpointReference>
885
        <Address>http://www.projectliberty.org/2006/01/role/paos</Address>
886
        <MetaData>
887
          <ServiceType>http://www.bsi.bund.de/ecard/api/1.1/PAOS/GetNextCommand</ServiceType>
888
        </MetaData>
889
      </EndpointReference>
890
    </PAOS>
891
    <ReplyTo xmlns="http://www.w3.org/2005/03/addressing">
892
      <Address>http://www.projectliberty.org/2006/02/role/paos</Address>
893
    </ReplyTo>
894
    <MessageID xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:9f817dfb-8bd9-4cba-b605-eaa4e68d992d</MessageID>
895
  </Header>
896
  <Body>
897
    <ns3:StartPAOS xmlns="http://www.bsi.bund.de/ecard/api/1.1" xmlns:ns10="urn:oasis:names:tc:SAML:1.0:assertion" xmlns:ns11="urn:oasis:names:tc:SAML:2.0:assertion" xmlns:ns12="http://www.w3.org/2001/04/xmlenc#" xmlns:ns13="http://ws.openecard.org/schema" xmlns:ns14="http://www.w3.org/2001/04/xmldsig-more#" xmlns:ns15="http://www.w3.org/2007/05/xmldsig-more#" xmlns:ns2="http://www.w3.org/2000/09/xmldsig#" xmlns:ns3="urn:iso:std:iso-iec:24727:tech:schema" xmlns:ns4="urn:oasis:names:tc:dss:1.0:core:schema" xmlns:ns5="http://uri.etsi.org/02231/v3.1.2#" xmlns:ns6="http://www.w3.org/2009/xmlenc11#" xmlns:ns7="http://www.setcce.org/schemas/ers" xmlns:ns8="urn:oasis:names:tc:dss-x:1.0:profiles:verificationreport:schema#" xmlns:ns9="http://uri.etsi.org/01903/v1.3.2#" Profile="http://www.bsi.bund.de/ecard/api/1.1">
898
      <ns3:SessionIdentifier>2e9ff28c-ef9c-45f9-8c39-15c68b416d68</ns3:SessionIdentifier>
899
      <ns3:ConnectionHandle>
900
        <ns3:ChannelHandle>
901
          <ns3:SessionIdentifier>C-AaenRmJCtZKKUzQvzqkw</ns3:SessionIdentifier>
902
        </ns3:ChannelHandle>
903
        <ns3:ContextHandle>8F27404E59BEC1306A299DCB3866A1D6</ns3:ContextHandle>
904
        <ns3:IFDName>REINER SCT cyberJack RFID basis 1</ns3:IFDName>
905
        <ns3:SlotIndex>0</ns3:SlotIndex>
906
        <ns3:CardApplication>3F00</ns3:CardApplication>
907
        <ns3:SlotHandle>CA04CD35965315933C47FAA7680FDA7F1CA49F109E698B57</ns3:SlotHandle>
908
        <ns3:RecognitionInfo>
909
          <ns3:CardType>http://bsi.bund.de/cif/npa.xml</ns3:CardType>
910
        </ns3:RecognitionInfo>
911
      </ns3:ConnectionHandle>
912
      <ns3:UserAgent>
913
        <ns3:Name>Open eCard App</ns3:Name>
914
        <ns3:VersionMajor>1</ns3:VersionMajor>
915
        <ns3:VersionMinor>3</ns3:VersionMinor>
916
        <ns3:VersionSubminor>0</ns3:VersionSubminor>
917
      </ns3:UserAgent>
918
      <ns3:SupportedAPIVersions>
919
        <ns3:Major>1</ns3:Major>
920
        <ns3:Minor>1</ns3:Minor>
921
        <ns3:Subminor>5</ns3:Subminor>
922
      </ns3:SupportedAPIVersions>
923
      <ns3:SupportedDIDProtocols>urn:oid:1.3.162.15480.3.0.14</ns3:SupportedDIDProtocols>
924
      <ns3:SupportedDIDProtocols>urn:oid:1.3.162.15480.3.0.14.2</ns3:SupportedDIDProtocols>
925
      <ns3:SupportedDIDProtocols>urn:oid:1.3.162.15480.3.0.25</ns3:SupportedDIDProtocols>
926
      <ns3:SupportedDIDProtocols>urn:oid:1.3.162.15480.3.0.9</ns3:SupportedDIDProtocols>
927
    </ns3:StartPAOS>
928
  </Body>
929
</Envelope>
930

    
931
2019-09-28 18:06:50,698+02 [PAOS] DEBUG org.openecard.transport.paos.PAOS:363 - Sending HTTP request.
932
2019-09-28 18:06:51,011+02 [PAOS] DEBUG org.openecard.transport.paos.PAOS:365 - HTTP response received.
933
2019-09-28 18:06:51,011+02 [PAOS] WARN  org.openecard.transport.paos.PAOS:495 - 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)
934
2019-09-28 18:06:51,011+02 [PAOS] DEBUG o.o.transport.httpcore.HttpUtils:112 - HTTP Response:
935
  HTTP/1.1 200 
936
  X-Content-Type-Options: nosniff
937
  X-XSS-Protection: 1; mode=block
938
  Cache-Control: no-cache, no-store, max-age=0, must-revalidate
939
  Pragma: no-cache
940
  Expires: 0
941
  Strict-Transport-Security: max-age=31536000 ; includeSubDomains
942
  X-Frame-Options: DENY
943
  Content-Type: application/vnd.paos+xml
944
  Content-Length: 7924
945
  Date: Sat, 28 Sep 2019 16:06:50 GMT
946
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
947
<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/">
948
   <soap:Header>
949
      <sb:Correlation xmlns:sb="http://urn:liberty:sb:2003-08" messageID="Id164" refToMessageID="2e9ff28c-ef9c-45f9-8c39-15c68b416d68"/>
950
      <RelatesTo xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:9f817dfb-8bd9-4cba-b605-eaa4e68d992d</RelatesTo>
951
      <MessageID xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:3afd3bfb-5339-4eac-ba55-33311fbc8c5a</MessageID>
952
   </soap:Header>
953
   <soap:Body>
954
   <ns3:DIDAuthenticate xmlns:ns2="urn:oasis:names:tc:dss:1.0:core:schema" xmlns:ns3="urn:iso:std:iso-iec:24727:tech:schema" xmlns:ns4="http://www.w3.org/2000/09/xmldsig#">
955
      <ns3:ConnectionHandle>
956
        <ns3:ChannelHandle>
957
          <ns3:SessionIdentifier>C-AaenRmJCtZKKUzQvzqkw</ns3:SessionIdentifier>
958
        </ns3:ChannelHandle>
959
        <ns3:ContextHandle>8F27404E59BEC1306A299DCB3866A1D6</ns3:ContextHandle>
960
        <ns3:IFDName>REINER SCT cyberJack RFID basis 1</ns3:IFDName>
961
        <ns3:SlotIndex>0</ns3:SlotIndex>
962
        <ns3:CardApplication>3F00</ns3:CardApplication>
963
        <ns3:SlotHandle>CA04CD35965315933C47FAA7680FDA7F1CA49F109E698B57</ns3:SlotHandle>
964
        <ns3:RecognitionInfo>
965
          <ns3:CardType>http://bsi.bund.de/cif/npa.xml</ns3:CardType>
966
        </ns3:RecognitionInfo>
967
      </ns3:ConnectionHandle>
968
      <ns3:DIDName>PIN</ns3:DIDName>
969
      <ns3:AuthenticationProtocolData xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" Protocol="urn:oid:1.3.162.15480.3.0.14.2" xsi:type="ns3:EAC1InputType">
970
        <Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201487f4e8201005f2901004210444544566549444454523130313434307f494f060a04007f0007020202020386410458f90bbe6a18117baa8771efcf5603578fb131ed20a351d90967b1c6a26beeb9a1f35d95969349b03a0a39baea121d17b4952f20bbfe1779c3e77ab7fb1d98155f200e444b6549444153444b30303238387f4c12060904007f000703010202530500011198045f25060109000902085f2406010901000001655e732d060904007f00070301030280202877f86655b0e1f13f41dbe7e7f8bff0e9778affe8ed86e17e84006340d3a478732d060904007f000703010301802077cb3f3f5c0859cb24dc7b181980ff49286b7210e7046d2ac8aeb9dace6f1de55f37403ba06114049e72488b7c8c183ae31a847931fc9ce0b68f1dff9e85fa6255cccd9d0d2d94cff2928c5a387da79a29856057464cc36d141b192c01f802f58be27d</Certificate>
971
        <Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201b67f4e82016e5f290100420e44454356434165494430303130327f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a78641048925419fc7f194922cfc6b8dd25ae6a19c1b59216e6cf06270e5d75cfd64205f55cf867bbfefeefd6e680e1fd197f18ab684484901362568efc9adb5c6018d728701015f200e44454356434165494430303130337f4c12060904007f0007030102025305fc0f13ffff5f25060102010200035f24060105010200035f37404d6f08a86a4f18409f6685387dd3c6a7ff5d68ea4f7714a861bbb3bb721d05d3014adf1763c9292f715d8e94ee9b3e1b73ab1382414ebf39dfb3b0fb6c09dbeb</Certificate>
972
        <Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201b67f4e82016e5f290100420e44454356434165494430303130337f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a7864104241d8627338b64f20077ffd558909a096c635ddb222852038eaae642e869a40173d588f817d95db2a6a0f077ea5ee63596a20f85bc3cb176d2f98d88d90219aa8701015f200e44454356434165494430303130347f4c12060904007f0007030102025305fc0f13ffff5f25060105000901045f24060108000901045f3740313a81ed8734e7a8c45f16b55fb603e63027b7f44c2de3a8e782552d35949db221ca33bd41a01da6a1288c7885714fc3a03fa45683b75d3884930ec6738af8a0</Certificate>
973
        <Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201b67f4e82016e5f290100420e44454356434165494430303130347f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a786410459d1a08a2572022e17fed831982a9cb904518003cf83dabed88dbed28963768b88dba22a153558bd21ddaa99318378b7cd7ebfe849557cd43f8526abe72734538701015f200e44454356434165494430303130357f4c12060904007f0007030102025305fc0f13ffff5f25060108000601025f24060201000601025f37402fbeeae1b1ade6cfb6cab9d9b19f6a6efacb7d9701997f43cf608bf72cf496f485f691e75190dec25c672b92cf9ba917883659a6dc16793d22bbec4019c616cc</Certificate>
974
        <Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f2181e77f4e81a05f290100420e44454356434165494430303130357f494f060a04007f000702020202038641045caa438d92fd3df22b6a58d438c1e6a6a30856228080b9ee2a8cb42694bc828a1283a21a38b78d9ca6b036aa69fc9797180ab27ee0d4114a2fc6f1bad2e8a2ab5f2010444544566549444454523130313434307f4c12060904007f0007030102025305400513ff975f25060109000702095f24060109010002075f374020df5b1be357da98df1377821739bc4d87a5275f5eb6196403dcbba1413840cf9deda4b6c420cc140313baa4225e89d5087e28a235a398cfa78f5bd8c6f60a92</Certificate>
975
        <CertificateDescription xmlns="urn:iso:std:iso-iec:24727:tech:schema">308202cc060a04007f00070301030101a10e0c0c442d547275737420476d6248a2181316687474703a2f2f7777772e642d74727573742e6e6574a3490c474964656e746966697a696572756e672066c3bc72204469656e73746520c3b66666656e746c6963686572205374656c6c656e20646573204c616e6465732044c3a46e656d61726ba41c131a68747470733a2f2f64652d6d772e6569642e64696773742e646ba58201e10c8201ddefbbbf4e616d652c20416e7363687269667420756e6420452d4d61696c2d4164726573736520646573204469656e737465616e626965746572733a0d0a546865204167656e637920666f7220446967697469736174696f6e20284d696e6973747279206f66207468652046696e616e6365290d0a4c616e6467726576656e20340d0a506f7374626f6b7320323139330d0a31303137204bc3b862656e6861766e204b0d0a64696773744064696773742e646b0d0a0d0a0d0a48696e7765697320617566206469652066c3bc722064656e204469656e737465616e626965746572207a757374c3a46e646967656e205374656c6c656e2c20646965206469652045696e68616c74756e672064657220566f7273636872696674656e207a756d20446174656e73636875747a206b6f6e74726f6c6c696572656e3a0d0a4469652042756e646573626561756674726167746520667565722064656e20446174656e73636875747a20756e642064696520496e666f726d6174696f6e7366726569686569740d0a4875736172656e73747261c39f652033300d0a353331313720426f6e6e0d0a446575747363686c616e640d0a2b34392028302920323238203939373739392d300d0a706f73747374656c6c6540626664692e62756e642e6465a74631440420627ded65df85f4445b4481374bdca46708b094d30d1b0ba6759879bbc67f240e0420903ba9a1e626947dcf2134a82d4f48c082992003dcac7d403d78c4d09440b8d4</CertificateDescription>
976
        <RequiredCHAT xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f4c12060904007f00070301020253050000009804</RequiredCHAT>
977
        <OptionalCHAT xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f4c12060904007f00070301020253050000000000</OptionalCHAT>
978
        <AuthenticatedAuxiliaryData xmlns="urn:iso:std:iso-iec:24727:tech:schema">67177315060904007f00070301040253083230313930393238</AuthenticatedAuxiliaryData>
979
        <TransactionInfo xmlns="urn:iso:std:iso-iec:24727:tech:schema"/>
980
      </ns3:AuthenticationProtocolData>
981
    </ns3:DIDAuthenticate>
982
  </soap:Body>
983
</soap:Envelope>
984

    
985

    
986
2019-09-28 18:06:51,013+02 [PAOS] DEBUG org.openecard.transport.paos.PAOS:224 - Message received:
987
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
988
<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/">
989
  <soap:Header>
990
    <sb:Correlation xmlns:sb="http://urn:liberty:sb:2003-08" messageID="Id164" refToMessageID="2e9ff28c-ef9c-45f9-8c39-15c68b416d68"/>
991
    <RelatesTo xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:9f817dfb-8bd9-4cba-b605-eaa4e68d992d</RelatesTo>
992
    <MessageID xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:3afd3bfb-5339-4eac-ba55-33311fbc8c5a</MessageID>
993
  </soap:Header>
994
  <soap:Body>
995
    <ns3:DIDAuthenticate xmlns:ns2="urn:oasis:names:tc:dss:1.0:core:schema" xmlns:ns3="urn:iso:std:iso-iec:24727:tech:schema" xmlns:ns4="http://www.w3.org/2000/09/xmldsig#">
996
      <ns3:ConnectionHandle>
997
        <ns3:ChannelHandle>
998
          <ns3:SessionIdentifier>C-AaenRmJCtZKKUzQvzqkw</ns3:SessionIdentifier>
999
        </ns3:ChannelHandle>
1000
        <ns3:ContextHandle>8F27404E59BEC1306A299DCB3866A1D6</ns3:ContextHandle>
1001
        <ns3:IFDName>REINER SCT cyberJack RFID basis 1</ns3:IFDName>
1002
        <ns3:SlotIndex>0</ns3:SlotIndex>
1003
        <ns3:CardApplication>3F00</ns3:CardApplication>
1004
        <ns3:SlotHandle>CA04CD35965315933C47FAA7680FDA7F1CA49F109E698B57</ns3:SlotHandle>
1005
        <ns3:RecognitionInfo>
1006
          <ns3:CardType>http://bsi.bund.de/cif/npa.xml</ns3:CardType>
1007
        </ns3:RecognitionInfo>
1008
      </ns3:ConnectionHandle>
1009
      <ns3:DIDName>PIN</ns3:DIDName>
1010
      <ns3:AuthenticationProtocolData xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" Protocol="urn:oid:1.3.162.15480.3.0.14.2" xsi:type="ns3:EAC1InputType">
1011
        <Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201487f4e8201005f2901004210444544566549444454523130313434307f494f060a04007f0007020202020386410458f90bbe6a18117baa8771efcf5603578fb131ed20a351d90967b1c6a26beeb9a1f35d95969349b03a0a39baea121d17b4952f20bbfe1779c3e77ab7fb1d98155f200e444b6549444153444b30303238387f4c12060904007f000703010202530500011198045f25060109000902085f2406010901000001655e732d060904007f00070301030280202877f86655b0e1f13f41dbe7e7f8bff0e9778affe8ed86e17e84006340d3a478732d060904007f000703010301802077cb3f3f5c0859cb24dc7b181980ff49286b7210e7046d2ac8aeb9dace6f1de55f37403ba06114049e72488b7c8c183ae31a847931fc9ce0b68f1dff9e85fa6255cccd9d0d2d94cff2928c5a387da79a29856057464cc36d141b192c01f802f58be27d</Certificate>
1012
        <Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201b67f4e82016e5f290100420e44454356434165494430303130327f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a78641048925419fc7f194922cfc6b8dd25ae6a19c1b59216e6cf06270e5d75cfd64205f55cf867bbfefeefd6e680e1fd197f18ab684484901362568efc9adb5c6018d728701015f200e44454356434165494430303130337f4c12060904007f0007030102025305fc0f13ffff5f25060102010200035f24060105010200035f37404d6f08a86a4f18409f6685387dd3c6a7ff5d68ea4f7714a861bbb3bb721d05d3014adf1763c9292f715d8e94ee9b3e1b73ab1382414ebf39dfb3b0fb6c09dbeb</Certificate>
1013
        <Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201b67f4e82016e5f290100420e44454356434165494430303130337f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a7864104241d8627338b64f20077ffd558909a096c635ddb222852038eaae642e869a40173d588f817d95db2a6a0f077ea5ee63596a20f85bc3cb176d2f98d88d90219aa8701015f200e44454356434165494430303130347f4c12060904007f0007030102025305fc0f13ffff5f25060105000901045f24060108000901045f3740313a81ed8734e7a8c45f16b55fb603e63027b7f44c2de3a8e782552d35949db221ca33bd41a01da6a1288c7885714fc3a03fa45683b75d3884930ec6738af8a0</Certificate>
1014
        <Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201b67f4e82016e5f290100420e44454356434165494430303130347f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a786410459d1a08a2572022e17fed831982a9cb904518003cf83dabed88dbed28963768b88dba22a153558bd21ddaa99318378b7cd7ebfe849557cd43f8526abe72734538701015f200e44454356434165494430303130357f4c12060904007f0007030102025305fc0f13ffff5f25060108000601025f24060201000601025f37402fbeeae1b1ade6cfb6cab9d9b19f6a6efacb7d9701997f43cf608bf72cf496f485f691e75190dec25c672b92cf9ba917883659a6dc16793d22bbec4019c616cc</Certificate>
1015
        <Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f2181e77f4e81a05f290100420e44454356434165494430303130357f494f060a04007f000702020202038641045caa438d92fd3df22b6a58d438c1e6a6a30856228080b9ee2a8cb42694bc828a1283a21a38b78d9ca6b036aa69fc9797180ab27ee0d4114a2fc6f1bad2e8a2ab5f2010444544566549444454523130313434307f4c12060904007f0007030102025305400513ff975f25060109000702095f24060109010002075f374020df5b1be357da98df1377821739bc4d87a5275f5eb6196403dcbba1413840cf9deda4b6c420cc140313baa4225e89d5087e28a235a398cfa78f5bd8c6f60a92</Certificate>
1016
        <CertificateDescription xmlns="urn:iso:std:iso-iec:24727:tech:schema">308202cc060a04007f00070301030101a10e0c0c442d547275737420476d6248a2181316687474703a2f2f7777772e642d74727573742e6e6574a3490c474964656e746966697a696572756e672066c3bc72204469656e73746520c3b66666656e746c6963686572205374656c6c656e20646573204c616e6465732044c3a46e656d61726ba41c131a68747470733a2f2f64652d6d772e6569642e64696773742e646ba58201e10c8201ddefbbbf4e616d652c20416e7363687269667420756e6420452d4d61696c2d4164726573736520646573204469656e737465616e626965746572733a0d0a546865204167656e637920666f7220446967697469736174696f6e20284d696e6973747279206f66207468652046696e616e6365290d0a4c616e6467726576656e20340d0a506f7374626f6b7320323139330d0a31303137204bc3b862656e6861766e204b0d0a64696773744064696773742e646b0d0a0d0a0d0a48696e7765697320617566206469652066c3bc722064656e204469656e737465616e626965746572207a757374c3a46e646967656e205374656c6c656e2c20646965206469652045696e68616c74756e672064657220566f7273636872696674656e207a756d20446174656e73636875747a206b6f6e74726f6c6c696572656e3a0d0a4469652042756e646573626561756674726167746520667565722064656e20446174656e73636875747a20756e642064696520496e666f726d6174696f6e7366726569686569740d0a4875736172656e73747261c39f652033300d0a353331313720426f6e6e0d0a446575747363686c616e640d0a2b34392028302920323238203939373739392d300d0a706f73747374656c6c6540626664692e62756e642e6465a74631440420627ded65df85f4445b4481374bdca46708b094d30d1b0ba6759879bbc67f240e0420903ba9a1e626947dcf2134a82d4f48c082992003dcac7d403d78c4d09440b8d4</CertificateDescription>
1017
        <RequiredCHAT xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f4c12060904007f00070301020253050000009804</RequiredCHAT>
1018
        <OptionalCHAT xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f4c12060904007f00070301020253050000000000</OptionalCHAT>
1019
        <AuthenticatedAuxiliaryData xmlns="urn:iso:std:iso-iec:24727:tech:schema">67177315060904007f00070301040253083230313930393238</AuthenticatedAuxiliaryData>
1020
        <TransactionInfo xmlns="urn:iso:std:iso-iec:24727:tech:schema"/>
1021
      </ns3:AuthenticationProtocolData>
1022
    </ns3:DIDAuthenticate>
1023
  </soap:Body>
1024
</soap:Envelope>
1025

    
1026
2019-09-28 18:06:51,017+02 [PAOS] DEBUG o.o.common.util.HandlerUtils:125 - Found ConnectionHandle in object of type DIDAuthenticate.
1027
2019-09-28 18:06:51,023+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1028
2019-09-28 18:06:51,024+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1029
2019-09-28 18:06:51,024+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1030
2019-09-28 18:06:51,024+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.DIDAuthenticate
1031
2019-09-28 18:06:51,025+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:71 - Requesting entry (filterAppId=true) for handle:
1032
ConnectionHandle:
1033
  Session: C-AaenRmJCtZKKUzQvzqkw
1034
  ContextHandle: 8F27404E59BEC1306A299DCB3866A1D6
1035
  IFDName: REINER SCT cyberJack RFID basis 1  SlotIndex: 0
1036
  SlotHandle: CA04CD35965315933C47FAA7680FDA7F1CA49F109E698B57
1037
  CardType: http://bsi.bund.de/cif/npa.xml
1038
2019-09-28 18:06:51,025+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:73 - Current state entries are:
1039
2019-09-28 18:06:51,025+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:75 - CardStateEntry@0 {
1040
  handle=  ConnectionHandle {
1041
    ctx=8F27404E59BEC1306A299DCB3866A1D6
1042
    ifd=REINER SCT cyberJack RFID basis 1
1043
    idx=0
1044
    slot=null
1045
    app=3F00
1046
    Recognition {
1047
      typ=http://bsi.bund.de/cif/npa.xml
1048
      ident=null
1049
    }
1050
  }
1051
}
1052

    
1053
2019-09-28 18:06:51,025+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:75 - CardStateEntry@1 {
1054
  handle=  ConnectionHandle {
1055
    ctx=8F27404E59BEC1306A299DCB3866A1D6
1056
    ifd=Alcor Micro USB Smart Card Reader 0
1057
    idx=0
1058
    slot=null
1059
    app=D2760001448000
1060
    Recognition {
1061
      typ=http://www.ihk.de/cif
1062
      ident=null
1063
    }
1064
  }
1065
}
1066

    
1067
2019-09-28 18:06:51,026+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:75 - CardStateEntry@2 {
1068
  handle=  ConnectionHandle {
1069
    ctx=8F27404E59BEC1306A299DCB3866A1D6
1070
    ifd=REINER SCT cyberJack RFID basis 1
1071
    idx=0
1072
    slot=CA04CD35965315933C47FAA7680FDA7F1CA49F109E698B57
1073
    app=3F00
1074
    Recognition {
1075
      typ=http://bsi.bund.de/cif/npa.xml
1076
      ident=null
1077
    }
1078
  }
1079
}
1080

    
1081
2019-09-28 18:06:51,032+02 [PAOS] WARN  org.openecard.common.I18n:152 - Failed to load resource eac for lang de_DE.
1082
2019-09-28 18:06:51,043+02 [PAOS] DEBUG o.o.common.util.HandlerUtils:132 - Found ContextHandle in object of type GetIFDCapabilities.
1083
2019-09-28 18:06:51,044+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1084
2019-09-28 18:06:51,045+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1085
2019-09-28 18:06:51,045+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1086
2019-09-28 18:06:51,045+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.GetIFDCapabilities
1087
2019-09-28 18:06:51,045+02 [PAOS] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'REINER SCT cyberJack RFID basis 1' is already connected.
1088
2019-09-28 18:06:51,051+02 [PAOS] WARN  o.o.ifd.scio.wrapper.TerminalInfo:323 - Unable to request features from reader.
1089
org.openecard.common.ifd.scio.SCIOException: Failed to transmit control command to the terminal 'REINER SCT cyberJack RFID basis 1'.
1090
	at org.openecard.scio.PCSCCard.transmitControlCommand(PCSCCard.java:110)
1091
	at org.openecard.ifd.scio.wrapper.SingleThreadChannel.lambda$transmitControlCommand$2(SingleThreadChannel.java:288)
1092
	at java.util.concurrent.FutureTask.run(Unknown Source)
1093
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
1094
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
1095
	at java.lang.Thread.run(Unknown Source)
1096
Caused by: javax.smartcardio.CardException: transmitControlCommand() failed
1097
	at sun.security.smartcardio.CardImpl.transmitControlCommand(Unknown Source)
1098
	at org.openecard.scio.PCSCCard.transmitControlCommand(PCSCCard.java:107)
1099
	... 5 common frames omitted
1100
Caused by: sun.security.smartcardio.PCSCException: Unknown error 0x32
1101
	at sun.security.smartcardio.PCSC.SCardControl(Native Method)
1102
	... 7 common frames omitted
1103
2019-09-28 18:06:51,052+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1104
2019-09-28 18:06:51,052+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1105
2019-09-28 18:06:51,053+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1106
2019-09-28 18:06:51,055+02 [PAOS] WARN  o.o.c.c.a.c.CardVerifiableCertificateChain:60 - Verification of the certificate chain is disabled.
1107
2019-09-28 18:06:51,056+02 [PAOS] ERROR o.o.sal.protocol.eac.PACEStep:490 - No eService TLS Certificate set in Dynamic Context.
1108
2019-09-28 18:06:51,056+02 [PAOS] DEBUG o.o.sal.protocol.eac.EACProtocol:100 - Checking if EAC protocol is finished.
1109
2019-09-28 18:06:51,056+02 [PAOS] DEBUG o.o.sal.protocol.eac.EACProtocol:106 - EAC AUTHENTICATION_DONE promise is delivered.
1110
2019-09-28 18:06:51,056+02 [PAOS] DEBUG o.o.sal.protocol.eac.EACProtocol:111 - EAC AUTHENTICATION_FAILED promise is delivered.
1111
2019-09-28 18:06:51,056+02 [PAOS] DEBUG o.o.sal.protocol.eac.EACProtocol:120 - EAC authentication finished=true.
1112
2019-09-28 18:06:51,056+02 [PAOS] DEBUG org.openecard.sal.TinySAL:2170 - SAL Protocol is finished, destroying protocol instance.
1113
2019-09-28 18:06:51,057+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:71 - Requesting entry (filterAppId=false) for handle:
1114
ConnectionHandle:
1115
  Session: C-AaenRmJCtZKKUzQvzqkw
1116
  ContextHandle: 8F27404E59BEC1306A299DCB3866A1D6
1117
  IFDName: REINER SCT cyberJack RFID basis 1  SlotIndex: 0
1118
  SlotHandle: CA04CD35965315933C47FAA7680FDA7F1CA49F109E698B57
1119
  CardType: http://bsi.bund.de/cif/npa.xml
1120
2019-09-28 18:06:51,057+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:73 - Current state entries are:
1121
2019-09-28 18:06:51,057+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:75 - CardStateEntry@0 {
1122
  handle=  ConnectionHandle {
1123
    ctx=8F27404E59BEC1306A299DCB3866A1D6
1124
    ifd=REINER SCT cyberJack RFID basis 1
1125
    idx=0
1126
    slot=null
1127
    app=3F00
1128
    Recognition {
1129
      typ=http://bsi.bund.de/cif/npa.xml
1130
      ident=null
1131
    }
1132
  }
1133
}
1134

    
1135
2019-09-28 18:06:51,057+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:75 - CardStateEntry@1 {
1136
  handle=  ConnectionHandle {
1137
    ctx=8F27404E59BEC1306A299DCB3866A1D6
1138
    ifd=Alcor Micro USB Smart Card Reader 0
1139
    idx=0
1140
    slot=null
1141
    app=D2760001448000
1142
    Recognition {
1143
      typ=http://www.ihk.de/cif
1144
      ident=null
1145
    }
1146
  }
1147
}
1148

    
1149
2019-09-28 18:06:51,058+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:75 - CardStateEntry@2 {
1150
  handle=  ConnectionHandle {
1151
    ctx=8F27404E59BEC1306A299DCB3866A1D6
1152
    ifd=REINER SCT cyberJack RFID basis 1
1153
    idx=0
1154
    slot=CA04CD35965315933C47FAA7680FDA7F1CA49F109E698B57
1155
    app=3F00
1156
    Recognition {
1157
      typ=http://bsi.bund.de/cif/npa.xml
1158
      ident=null
1159
    }
1160
  }
1161
  protocol=urn:oid:1.3.162.15480.3.0.14.2
1162
}
1163

    
1164
2019-09-28 18:06:51,058+02 [PAOS] DEBUG o.o.sal.protocol.eac.EACProtocol:71 - Destroying EAC protocol instance.
1165
2019-09-28 18:06:51,062+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1166
2019-09-28 18:06:51,062+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1167
2019-09-28 18:06:51,062+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1168
2019-09-28 18:06:51,063+02 [PAOS] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request (before adding content):
1169
  POST /eidas-middleware/paosreceiver HTTP/1.1
1170
  Connection: keep-alive
1171
  User-Agent: Open eCard App/1.3.0
1172
  Host: de-mw.eid.digst.dk:443
1173
  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:Hash";"urn:iso:std:iso-iec:24727:tech:schema:Encipher";"urn:iso:std:iso-iec:24727:tech:schema:DSIList";"urn:iso:std:iso-iec:24727:tech:schema:DSIRead";"urn:iso:std:iso-iec:24727:tech:schema:DSIWrite";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationServiceList";"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:VerifySignature";"urn:iso:std:iso-iec:24727:tech:schema:GetRandom";"urn:iso:std:iso-iec:24727:tech:schema:DIDAuthenticate";"urn:iso:std:iso-iec:24727:tech:schema:DataSetSelect";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationList";"urn:iso:std:iso-iec:24727:tech:schema:VerifyCertificate";"urn:iso:std:iso-iec:24727:tech:schema:DataSetList";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationServiceDescribe";"urn:iso:std:iso-iec:24727:tech:schema:Sign";"urn:iso:std:iso-iec:24727:tech:schema:DIDGet";"urn:iso:std:iso-iec:24727:tech:schema:DIDList";"urn:iso:std:iso-iec:24727:tech:schema:ACLList";"urn:iso:std:iso-iec:24727:tech:schema:Decipher"
1174
  Accept: text/xml, application/xml, application/vnd.paos+xml
1175

    
1176
2019-09-28 18:06:51,064+02 [PAOS] DEBUG org.openecard.transport.paos.PAOS:268 - Message sent:
1177
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
1178
<Envelope xmlns="http://schemas.xmlsoap.org/soap/envelope/">
1179
  <Header>
1180
    <PAOS xmlns:ns0="http://schemas.xmlsoap.org/soap/envelope/" ns0:actor="http://schemas.xmlsoap.org/soap/actor/next" xmlns:ns1="http://schemas.xmlsoap.org/soap/envelope/" ns1:mustUnderstand="1" xmlns="urn:liberty:paos:2006-08">
1181
      <Version>urn:liberty:paos:2006-08</Version>
1182
      <EndpointReference>
1183
        <Address>http://www.projectliberty.org/2006/01/role/paos</Address>
1184
        <MetaData>
1185
          <ServiceType>http://www.bsi.bund.de/ecard/api/1.1/PAOS/GetNextCommand</ServiceType>
1186
        </MetaData>
1187
      </EndpointReference>
1188
    </PAOS>
1189
    <ReplyTo xmlns="http://www.w3.org/2005/03/addressing">
1190
      <Address>http://www.projectliberty.org/2006/02/role/paos</Address>
1191
    </ReplyTo>
1192
    <RelatesTo xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:3afd3bfb-5339-4eac-ba55-33311fbc8c5a</RelatesTo>
1193
    <MessageID xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:cba7170b-8dba-47ad-ab2c-58d0315ffaed</MessageID>
1194
  </Header>
1195
  <Body>
1196
    <ns3:DIDAuthenticateResponse xmlns="http://www.bsi.bund.de/ecard/api/1.1" xmlns:ns10="urn:oasis:names:tc:SAML:1.0:assertion" xmlns:ns11="urn:oasis:names:tc:SAML:2.0:assertion" xmlns:ns12="http://www.w3.org/2001/04/xmlenc#" xmlns:ns13="http://ws.openecard.org/schema" xmlns:ns14="http://www.w3.org/2001/04/xmldsig-more#" xmlns:ns15="http://www.w3.org/2007/05/xmldsig-more#" xmlns:ns2="http://www.w3.org/2000/09/xmldsig#" xmlns:ns3="urn:iso:std:iso-iec:24727:tech:schema" xmlns:ns4="urn:oasis:names:tc:dss:1.0:core:schema" xmlns:ns5="http://uri.etsi.org/02231/v3.1.2#" xmlns:ns6="http://www.w3.org/2009/xmlenc11#" xmlns:ns7="http://www.setcce.org/schemas/ers" xmlns:ns8="urn:oasis:names:tc:dss-x:1.0:profiles:verificationreport:schema#" xmlns:ns9="http://uri.etsi.org/01903/v1.3.2#" Profile="http://www.bsi.bund.de/ecard/api/1.1">
1197
      <ns4:Result>
1198
        <ns4:ResultMajor>http://www.bsi.bund.de/ecard/api/1.1/resultmajor#error</ns4:ResultMajor>
1199
        <ns4:ResultMinor>http://www.bsi.bund.de/ecard/api/1.1/resultminor/sal#prerequisitesNotSatisfied</ns4:ResultMinor>
1200
        <ns4:ResultMessage xml:lang="en">Hash of eService certificate is NOT contained in the CertificateDescription.</ns4:ResultMessage>
1201
      </ns4:Result>
1202
      <ns3:AuthenticationProtocolData xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" Protocol="urn:oid:1.3.162.15480.3.0.14.2" xsi:type="ns3:EmptyResponseDataType"/>
1203
    </ns3:DIDAuthenticateResponse>
1204
  </Body>
1205
</Envelope>
1206

    
1207
2019-09-28 18:06:51,064+02 [PAOS] DEBUG org.openecard.transport.paos.PAOS:363 - Sending HTTP request.
1208
2019-09-28 18:06:51,337+02 [PAOS] DEBUG org.openecard.transport.paos.PAOS:365 - HTTP response received.
1209
2019-09-28 18:06:51,337+02 [PAOS] WARN  org.openecard.transport.paos.PAOS:495 - 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)
1210
2019-09-28 18:06:51,337+02 [PAOS] DEBUG o.o.transport.httpcore.HttpUtils:112 - HTTP Response:
1211
  HTTP/1.1 200 
1212
  X-Content-Type-Options: nosniff
1213
  X-XSS-Protection: 1; mode=block
1214
  Cache-Control: no-cache, no-store, max-age=0, must-revalidate
1215
  Pragma: no-cache
1216
  Expires: 0
1217
  Strict-Transport-Security: max-age=31536000 ; includeSubDomains
1218
  X-Frame-Options: DENY
1219
  Content-Type: application/vnd.paos+xml
1220
  Content-Length: 1186
1221
  Date: Sat, 28 Sep 2019 16:06:50 GMT
1222
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
1223
<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/">
1224
   <soap:Header>
1225
      <sb:Correlation xmlns:sb="http://urn:liberty:sb:2003-08" messageID="Id165" refToMessageID="2e9ff28c-ef9c-45f9-8c39-15c68b416d68"/>
1226
      <RelatesTo xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:cba7170b-8dba-47ad-ab2c-58d0315ffaed</RelatesTo>
1227
      <MessageID xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:146ef823-472b-4a15-8d73-957383fd4f37</MessageID>
1228
   </soap:Header>
1229
   <soap:Body>
1230
   <ns3:StartPAOSResponse xmlns:ns2="urn:oasis:names:tc:dss:1.0:core:schema" xmlns:ns3="urn:iso:std:iso-iec:24727:tech:schema" xmlns:ns4="http://www.w3.org/2000/09/xmldsig#">
1231
      <ns2:Result>
1232
        <ns2:ResultMajor>http://www.bsi.bund.de/ecard/api/1.1/resultmajor#error</ns2:ResultMajor>
1233
        <ns2:ResultMinor>http://www.bsi.bund.de/ecard/api/1.1/resultminor/sal#prerequisitesNotSatisfied</ns2:ResultMinor>
1234
        <ns2:ResultMessage xml:lang="en">Hash of eService certificate is NOT contained in the CertificateDescription.</ns2:ResultMessage>
1235
      </ns2:Result>
1236
    </ns3:StartPAOSResponse>
1237
  </soap:Body>
1238
</soap:Envelope>
1239

    
1240

    
1241
2019-09-28 18:06:51,338+02 [PAOS] DEBUG org.openecard.transport.paos.PAOS:224 - Message received:
1242
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
1243
<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/">
1244
  <soap:Header>
1245
    <sb:Correlation xmlns:sb="http://urn:liberty:sb:2003-08" messageID="Id165" refToMessageID="2e9ff28c-ef9c-45f9-8c39-15c68b416d68"/>
1246
    <RelatesTo xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:cba7170b-8dba-47ad-ab2c-58d0315ffaed</RelatesTo>
1247
    <MessageID xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:146ef823-472b-4a15-8d73-957383fd4f37</MessageID>
1248
  </soap:Header>
1249
  <soap:Body>
1250
    <ns3:StartPAOSResponse xmlns:ns2="urn:oasis:names:tc:dss:1.0:core:schema" xmlns:ns3="urn:iso:std:iso-iec:24727:tech:schema" xmlns:ns4="http://www.w3.org/2000/09/xmldsig#">
1251
      <ns2:Result>
1252
        <ns2:ResultMajor>http://www.bsi.bund.de/ecard/api/1.1/resultmajor#error</ns2:ResultMajor>
1253
        <ns2:ResultMinor>http://www.bsi.bund.de/ecard/api/1.1/resultminor/sal#prerequisitesNotSatisfied</ns2:ResultMinor>
1254
        <ns2:ResultMessage xml:lang="en">Hash of eService certificate is NOT contained in the CertificateDescription.</ns2:ResultMessage>
1255
      </ns2:Result>
1256
    </ns3:StartPAOSResponse>
1257
  </soap:Body>
1258
</soap:Envelope>
1259

    
1260
2019-09-28 18:06:51,338+02 [PAOS] WARN  org.openecard.transport.paos.PAOS:233 - Received message without Profile attribute, adding one for proper validation.
1261
2019-09-28 18:06:51,339+02 [PAOS] INFO  o.o.c.t.ClientCertDefaultTlsClient:298 - TLS warning sent.
1262
2019-09-28 18:06:51,340+02 [PAOS] INFO  o.o.c.t.ClientCertDefaultTlsClient:300 - TLS(WARN): Close [close_notify=0] --> Connection closed
1263
2019-09-28 18:06:51,340+02 [PAOS] DEBUG o.o.common.util.HandlerUtils:125 - Found ConnectionHandle in object of type CardApplicationDisconnect.
1264
2019-09-28 18:06:51,341+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1265
2019-09-28 18:06:51,342+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1266
2019-09-28 18:06:51,342+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1267
2019-09-28 18:06:51,342+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.CardApplicationDisconnect
1268
2019-09-28 18:06:51,342+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:135 - Removing CardStateEntries for slot=CA04CD35965315933C47FAA7680FDA7F1CA49F109E698B57.
1269
2019-09-28 18:06:51,342+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:114 - Removing CardStateEntries based on connection handle.
1270
ConnectionHandle:
1271
  ContextHandle: 8F27404E59BEC1306A299DCB3866A1D6
1272
  SlotHandle: CA04CD35965315933C47FAA7680FDA7F1CA49F109E698B57
1273
2019-09-28 18:06:51,342+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:160 - Internal removeEntry function called with removeSlotHandles=false.
1274
2019-09-28 18:06:51,342+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:165 - Removing entry from session map for channel session=C-AaenRmJCtZKKUzQvzqkw.
1275
2019-09-28 18:06:51,343+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:168 - Removing entry from context map for ctx=8F27404E59BEC1306A299DCB3866A1D6.
1276
2019-09-28 18:06:51,343+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:180 - Removing entry for slot=CA04CD35965315933C47FAA7680FDA7F1CA49F109E698B57.
1277
2019-09-28 18:06:51,343+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:184 - Removing all protocol instances.
1278
2019-09-28 18:06:51,343+02 [PAOS] DEBUG o.o.common.sal.state.CardStateEntry:172 - Removing 0 protocols from card state entry.
1279
2019-09-28 18:06:51,343+02 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:187 - Removing entry from allEntries set.
1280
2019-09-28 18:06:51,343+02 [PAOS] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Disconnect.
1281
2019-09-28 18:06:51,344+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1282
2019-09-28 18:06:51,344+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1283
2019-09-28 18:06:51,344+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1284
2019-09-28 18:06:51,344+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Disconnect
1285
2019-09-28 18:06:51,416+02 [PAOS] INFO  o.o.i.s.wrapper.SingleThreadChannel:139 - Card connected with protocol T=1.
1286
2019-09-28 18:06:51,417+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_REMOVED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1287
2019-09-28 18:06:51,417+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_REMOVED to EventCallback org.openecard.addon.EventHandler@ea6137.
1288
2019-09-28 18:06:51,417+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_REMOVED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
1289
2019-09-28 18:06:51,417+02 [Dispatcher Event 0] INFO  o.o.c.sal.state.SALStateCallback:75 - Remove ConnectionHandle from SAL.
1290
ConnectionHandle:
1291
  ContextHandle: 8F27404E59BEC1306A299DCB3866A1D6
1292
  IFDName: REINER SCT cyberJack RFID basis 1  SlotIndex: 0
1293
2019-09-28 18:06:51,417+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: CARD_REMOVED
1294
2019-09-28 18:06:51,417+02 [PAOS] DEBUG o.o.common.util.HandlerUtils:132 - Found ContextHandle in object of type GetIFDCapabilities.
1295
2019-09-28 18:06:51,417+02 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:114 - Removing CardStateEntries based on connection handle.
1296
ConnectionHandle:
1297
  ContextHandle: 8F27404E59BEC1306A299DCB3866A1D6
1298
  IFDName: REINER SCT cyberJack RFID basis 1  SlotIndex: 0
1299
2019-09-28 18:06:51,417+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=REINER SCT cyberJack RFID basis 1, slot=null, ctx=8F27404E59BEC1306A299DCB3866A1D6
1300
2019-09-28 18:06:51,417+02 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:160 - Internal removeEntry function called with removeSlotHandles=true.
1301
2019-09-28 18:06:51,417+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:394 - RecognitionInfo: null
1302
2019-09-28 18:06:51,417+02 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:165 - Removing entry from session map for channel session=C-AaenRmJCtZKKUzQvzqkw.
1303
2019-09-28 18:06:51,417+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
1304
2019-09-28 18:06:51,418+02 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:168 - Removing entry from context map for ctx=8F27404E59BEC1306A299DCB3866A1D6.
1305
2019-09-28 18:06:51,418+02 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:172 - Removing all entries for SlotHandles.
1306
2019-09-28 18:06:51,418+02 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:184 - Removing all protocol instances.
1307
2019-09-28 18:06:51,418+02 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateEntry:172 - Removing 0 protocols from card state entry.
1308
2019-09-28 18:06:51,418+02 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:187 - Removing entry from allEntries set.
1309
2019-09-28 18:06:51,418+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1310
2019-09-28 18:06:51,419+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1311
2019-09-28 18:06:51,419+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1312
2019-09-28 18:06:51,419+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.GetIFDCapabilities
1313
2019-09-28 18:06:51,419+02 [PAOS] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'REINER SCT cyberJack RFID basis 1' is already connected.
1314
2019-09-28 18:06:51,427+02 [PAOS] WARN  o.o.ifd.scio.wrapper.TerminalInfo:323 - Unable to request features from reader.
1315
org.openecard.common.ifd.scio.SCIOException: Failed to transmit control command to the terminal 'REINER SCT cyberJack RFID basis 1'.
1316
	at org.openecard.scio.PCSCCard.transmitControlCommand(PCSCCard.java:110)
1317
	at org.openecard.ifd.scio.wrapper.SingleThreadChannel.lambda$transmitControlCommand$2(SingleThreadChannel.java:288)
1318
	at java.util.concurrent.FutureTask.run(Unknown Source)
1319
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
1320
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
1321
	at java.lang.Thread.run(Unknown Source)
1322
Caused by: javax.smartcardio.CardException: transmitControlCommand() failed
1323
	at sun.security.smartcardio.CardImpl.transmitControlCommand(Unknown Source)
1324
	at org.openecard.scio.PCSCCard.transmitControlCommand(PCSCCard.java:107)
1325
	... 5 common frames omitted
1326
Caused by: sun.security.smartcardio.PCSCException: Unknown error 0x32
1327
	at sun.security.smartcardio.PCSC.SCardControl(Native Method)
1328
	... 7 common frames omitted
1329
2019-09-28 18:06:51,430+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1330
2019-09-28 18:06:51,430+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1331
2019-09-28 18:06:51,430+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1332
2019-09-28 18:06:51,430+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_INSERTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1333
2019-09-28 18:06:51,430+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_INSERTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1334
2019-09-28 18:06:51,431+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_INSERTED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
1335
2019-09-28 18:06:51,433+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:132 - Found ContextHandle in object of type Connect.
1336
2019-09-28 18:06:51,434+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: CARD_INSERTED
1337
2019-09-28 18:06:51,434+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=REINER SCT cyberJack RFID basis 1, slot=null, ctx=8F27404E59BEC1306A299DCB3866A1D6
1338
2019-09-28 18:06:51,434+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:392 - RecognitionInfo: http://bsi.bund.de/cif/unknown, 3B8780018031B8738401E019
1339
2019-09-28 18:06:51,435+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
1340
2019-09-28 18:06:51,437+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1341
2019-09-28 18:06:51,437+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1342
2019-09-28 18:06:51,437+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1343
2019-09-28 18:06:51,438+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Connect
1344
2019-09-28 18:06:51,438+02 [Recoginiton-1] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'REINER SCT cyberJack RFID basis 1' is already connected.
1345
2019-09-28 18:06:51,438+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1346
2019-09-28 18:06:51,438+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1347
2019-09-28 18:06:51,438+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1348
2019-09-28 18:06:51,447+02 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1349
2019-09-28 18:06:51,447+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1350
2019-09-28 18:06:51,447+02 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1351
2019-09-28 18:06:51,448+02 [Thread-9] ERROR o.o.binding.tctoken.TCTokenHandler:431 - org.openecard.transport.paos.PAOSException: http://www.bsi.bund.de/ecard/api/1.1/resultminor/sal#prerequisitesNotSatisfied
1352
  ==> Hash of eService certificate is NOT contained in the CertificateDescription.
1353
java.util.concurrent.ExecutionException: org.openecard.transport.paos.PAOSException: http://www.bsi.bund.de/ecard/api/1.1/resultminor/sal#prerequisitesNotSatisfied
1354
  ==> Hash of eService certificate is NOT contained in the CertificateDescription.
1355
	at java.util.concurrent.FutureTask.report(Unknown Source)
1356
	at java.util.concurrent.FutureTask.get(Unknown Source)
1357
	at org.openecard.binding.tctoken.TCTokenHandler.waitForTask(TCTokenHandler.java:425)
1358
	at org.openecard.binding.tctoken.TCTokenHandler.processBinding(TCTokenHandler.java:234)
1359
	at org.openecard.binding.tctoken.TCTokenHandler.handleActivate(TCTokenHandler.java:337)
1360
	at org.openecard.addons.activate.ActivateAction.processTcToken(ActivateAction.java:409)
1361
	at org.openecard.addons.activate.ActivateAction.processRequest(ActivateAction.java:265)
1362
	at org.openecard.addons.activate.ActivateAction.checkRequestParameters(ActivateAction.java:246)
1363
	at org.openecard.addons.activate.ActivateAction.execute(ActivateAction.java:127)
1364
	at org.openecard.addon.bind.AppPluginActionProxy.execute(AppPluginActionProxy.java:55)
1365
	at org.openecard.control.binding.http.handler.HttpAppPluginActionHandler.handle(HttpAppPluginActionHandler.java:127)
1366
	at org.openecard.apache.http.protocol.HttpService.doService(HttpService.java:437)
1367
	at org.openecard.apache.http.protocol.HttpService.handleRequest(HttpService.java:342)
1368
	at org.openecard.control.binding.http.HttpService$1.run(HttpService.java:132)
1369
Caused by: org.openecard.transport.paos.PAOSException: org.openecard.common.WSHelper$WSException: http://www.bsi.bund.de/ecard/api/1.1/resultminor/sal#prerequisitesNotSatisfied
1370
  ==> Hash of eService certificate is NOT contained in the CertificateDescription.
1371
	at org.openecard.transport.paos.PAOS.sendStartPAOS(PAOS.java:454)
1372
	at org.openecard.binding.tctoken.PAOSTask.call(PAOSTask.java:112)
1373
	at org.openecard.binding.tctoken.PAOSTask.call(PAOSTask.java:53)
1374
	at java.util.concurrent.FutureTask.run(Unknown Source)
1375
	at java.lang.Thread.run(Unknown Source)
1376
Caused by: org.openecard.common.WSHelper$WSException: http://www.bsi.bund.de/ecard/api/1.1/resultminor/sal#prerequisitesNotSatisfied
1377
  ==> Hash of eService certificate is NOT contained in the CertificateDescription.
1378
	at org.openecard.common.ECardException.makeException(ECardException.java:64)
1379
	at org.openecard.common.WSHelper$WSException.<init>(WSHelper.java:47)
1380
	at org.openecard.common.WSHelper.checkResult(WSHelper.java:69)
1381
	at org.openecard.transport.paos.PAOS.sendStartPAOS(PAOS.java:402)
1382
	... 4 common frames omitted
1383
2019-09-28 18:06:51,449+02 [Thread-9] ERROR o.o.binding.tctoken.TCTokenHandler:350 - org.openecard.common.WSHelper$WSException: http://www.bsi.bund.de/ecard/api/1.1/resultminor/sal#prerequisitesNotSatisfied
1384
  ==> Hash of eService certificate is NOT contained in the CertificateDescription.
1385
org.openecard.transport.paos.PAOSException: org.openecard.common.WSHelper$WSException: http://www.bsi.bund.de/ecard/api/1.1/resultminor/sal#prerequisitesNotSatisfied
1386
  ==> Hash of eService certificate is NOT contained in the CertificateDescription.
1387
	at org.openecard.transport.paos.PAOS.sendStartPAOS(PAOS.java:454)
1388
	at org.openecard.binding.tctoken.PAOSTask.call(PAOSTask.java:112)
1389
	at org.openecard.binding.tctoken.PAOSTask.call(PAOSTask.java:53)
1390
	at java.util.concurrent.FutureTask.run(Unknown Source)
1391
	at java.lang.Thread.run(Unknown Source)
1392
Caused by: org.openecard.common.WSHelper$WSException: http://www.bsi.bund.de/ecard/api/1.1/resultminor/sal#prerequisitesNotSatisfied
1393
  ==> Hash of eService certificate is NOT contained in the CertificateDescription.
1394
	at org.openecard.common.ECardException.makeException(ECardException.java:64)
1395
	at org.openecard.common.WSHelper$WSException.<init>(WSHelper.java:47)
1396
	at org.openecard.common.WSHelper.checkResult(WSHelper.java:69)
1397
	at org.openecard.transport.paos.PAOS.sendStartPAOS(PAOS.java:402)
1398
	... 4 common frames omitted
1399
2019-09-28 18:06:51,450+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1400
2019-09-28 18:06:51,450+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1401
2019-09-28 18:06:51,450+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1402
2019-09-28 18:06:51,450+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type BeginTransaction.
1403
2019-09-28 18:06:51,451+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1404
2019-09-28 18:06:51,451+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1405
2019-09-28 18:06:51,452+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1406
2019-09-28 18:06:51,452+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.BeginTransaction
1407
2019-09-28 18:06:51,453+02 [Thread-9] INFO  o.o.binding.tctoken.ResourceContext:207 - Trying to load resource from: https://de-mw.eid.digst.dk/eidas-middleware/ResponseSender?refID=460f2db4-cf73-4338-800a-ba53c82059da
1408
2019-09-28 18:06:51,453+02 [Thread-9] DEBUG o.o.crypto.tls.proxy.ProxySettings:133 - Selecting proxy: DIRECT
1409
2019-09-28 18:06:51,453+02 [Thread-9] DEBUG o.o.crypto.tls.proxy.ProxySettings:168 - Using proxy (DIRECT) to obtain socket.
1410
2019-09-28 18:06:51,458+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1411
2019-09-28 18:06:51,458+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1412
2019-09-28 18:06:51,459+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1413
2019-09-28 18:06:51,459+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
1414
2019-09-28 18:06:51,459+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1415
2019-09-28 18:06:51,460+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1416
2019-09-28 18:06:51,460+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1417
2019-09-28 18:06:51,460+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
1418
2019-09-28 18:06:51,460+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
1419
2019-09-28 18:06:51,491+02 [Thread-9] DEBUG o.o.binding.tctoken.ResourceContext:244 - Performing TLS handshake.
1420
2019-09-28 18:06:51,494+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
1421
2019-09-28 18:06:51,497+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1422
2019-09-28 18:06:51,497+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1423
2019-09-28 18:06:51,497+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1424
2019-09-28 18:06:51,497+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
1425
2019-09-28 18:06:51,499+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1426
2019-09-28 18:06:51,499+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1427
2019-09-28 18:06:51,499+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1428
2019-09-28 18:06:51,499+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
1429
2019-09-28 18:06:51,499+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C020003
1430
2019-09-28 18:06:51,506+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6A82
1431
2019-09-28 18:06:51,509+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1432
2019-09-28 18:06:51,509+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1433
2019-09-28 18:06:51,510+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1434
2019-09-28 18:06:51,510+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
1435
2019-09-28 18:06:51,511+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1436
2019-09-28 18:06:51,511+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1437
2019-09-28 18:06:51,511+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1438
2019-09-28 18:06:51,512+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
1439
2019-09-28 18:06:51,512+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
1440
2019-09-28 18:06:51,520+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
1441
2019-09-28 18:06:51,523+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1442
2019-09-28 18:06:51,523+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1443
2019-09-28 18:06:51,523+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1444
2019-09-28 18:06:51,524+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
1445
2019-09-28 18:06:51,525+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1446
2019-09-28 18:06:51,526+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1447
2019-09-28 18:06:51,526+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1448
2019-09-28 18:06:51,526+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
1449
2019-09-28 18:06:51,526+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C022F00
1450
2019-09-28 18:06:51,542+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
1451
2019-09-28 18:06:51,545+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1452
2019-09-28 18:06:51,545+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1453
2019-09-28 18:06:51,545+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1454
2019-09-28 18:06:51,545+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
1455
2019-09-28 18:06:51,546+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1456
2019-09-28 18:06:51,546+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1457
2019-09-28 18:06:51,546+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1458
2019-09-28 18:06:51,546+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
1459
2019-09-28 18:06:51,546+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00B20404FF
1460
2019-09-28 18:06:51,552+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6D00
1461
2019-09-28 18:06:51,555+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1462
2019-09-28 18:06:51,556+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1463
2019-09-28 18:06:51,556+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1464
2019-09-28 18:06:51,556+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
1465
2019-09-28 18:06:51,557+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1466
2019-09-28 18:06:51,557+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1467
2019-09-28 18:06:51,557+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1468
2019-09-28 18:06:51,557+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
1469
2019-09-28 18:06:51,557+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
1470
2019-09-28 18:06:51,564+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
1471
2019-09-28 18:06:51,566+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1472
2019-09-28 18:06:51,566+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1473
2019-09-28 18:06:51,566+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1474
2019-09-28 18:06:51,566+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
1475
2019-09-28 18:06:51,567+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1476
2019-09-28 18:06:51,567+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1477
2019-09-28 18:06:51,567+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1478
2019-09-28 18:06:51,567+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
1479
2019-09-28 18:06:51,567+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C022F00
1480
2019-09-28 18:06:51,575+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
1481
2019-09-28 18:06:51,578+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1482
2019-09-28 18:06:51,578+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1483
2019-09-28 18:06:51,578+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1484
2019-09-28 18:06:51,579+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
1485
2019-09-28 18:06:51,580+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1486
2019-09-28 18:06:51,580+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1487
2019-09-28 18:06:51,580+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1488
2019-09-28 18:06:51,580+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
1489
2019-09-28 18:06:51,580+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00B20304FF
1490
2019-09-28 18:06:51,586+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6D00
1491
2019-09-28 18:06:51,588+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1492
2019-09-28 18:06:51,588+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1493
2019-09-28 18:06:51,588+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1494
2019-09-28 18:06:51,588+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
1495
2019-09-28 18:06:51,590+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1496
2019-09-28 18:06:51,590+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1497
2019-09-28 18:06:51,590+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1498
2019-09-28 18:06:51,590+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
1499
2019-09-28 18:06:51,590+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4040C0FF04573744549442076657220312E30
1500
2019-09-28 18:06:51,602+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6A82
1501
2019-09-28 18:06:51,605+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1502
2019-09-28 18:06:51,605+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1503
2019-09-28 18:06:51,606+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1504
2019-09-28 18:06:51,606+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
1505
2019-09-28 18:06:51,608+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1506
2019-09-28 18:06:51,608+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1507
2019-09-28 18:06:51,608+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1508
2019-09-28 18:06:51,609+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
1509
2019-09-28 18:06:51,609+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4040C0FD23300000045737445494420763335
1510
2019-09-28 18:06:51,616+02 [Thread-9] DEBUG o.o.c.tls.verify.HostnameVerifier:126 - Comparing connection hostname against certificate hostname: [de-mw.eid.digst.dk] [de-mw.eid.digst.dk]
1511
2019-09-28 18:06:51,619+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6A82
1512
2019-09-28 18:06:51,624+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1513
2019-09-28 18:06:51,624+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1514
2019-09-28 18:06:51,625+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1515
2019-09-28 18:06:51,625+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
1516
2019-09-28 18:06:51,627+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1517
2019-09-28 18:06:51,627+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1518
2019-09-28 18:06:51,627+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1519
2019-09-28 18:06:51,628+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
1520
2019-09-28 18:06:51,628+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
1521
2019-09-28 18:06:51,637+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
1522
2019-09-28 18:06:51,641+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1523
2019-09-28 18:06:51,641+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1524
2019-09-28 18:06:51,641+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1525
2019-09-28 18:06:51,641+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
1526
2019-09-28 18:06:51,641+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1527
2019-09-28 18:06:51,641+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1528
2019-09-28 18:06:51,641+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1529
2019-09-28 18:06:51,641+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
1530
2019-09-28 18:06:51,641+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C022F00
1531
2019-09-28 18:06:51,649+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
1532
2019-09-28 18:06:51,651+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1533
2019-09-28 18:06:51,651+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1534
2019-09-28 18:06:51,651+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1535
2019-09-28 18:06:51,651+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
1536
2019-09-28 18:06:51,652+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1537
2019-09-28 18:06:51,653+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1538
2019-09-28 18:06:51,653+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1539
2019-09-28 18:06:51,653+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
1540
2019-09-28 18:06:51,653+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00B00000FF
1541
2019-09-28 18:06:51,666+02 [Recoginiton-1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 61324F0FE828BD080FA000000167455349474E500F434941207A752044462E655369676E5100730C4F0AA000000167455349474E61094F07A0000002471001610B4F09E80704007F00070302610C4F0AA000000167455349474E6282
1542
2019-09-28 18:06:51,699+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1543
2019-09-28 18:06:51,700+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1544
2019-09-28 18:06:51,701+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1545
2019-09-28 18:06:51,701+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type EndTransaction.
1546
2019-09-28 18:06:51,705+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1547
2019-09-28 18:06:51,706+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1548
2019-09-28 18:06:51,706+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1549
2019-09-28 18:06:51,707+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.EndTransaction
1550
2019-09-28 18:06:51,712+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1551
2019-09-28 18:06:51,712+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1552
2019-09-28 18:06:51,712+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1553
2019-09-28 18:06:51,712+02 [Recoginiton-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Disconnect.
1554
2019-09-28 18:06:51,714+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
1555
2019-09-28 18:06:51,714+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1556
2019-09-28 18:06:51,714+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@ea6137.
1557
2019-09-28 18:06:51,714+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Disconnect
1558
2019-09-28 18:06:51,721+02 [Recoginiton-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
1559
2019-09-28 18:06:51,721+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1560
2019-09-28 18:06:51,721+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@ea6137.
1561
2019-09-28 18:06:51,722+02 [Recoginiton-1] DEBUG org.openecard.ifd.event.Recognizer:60 - Found a recognized card event (REINER SCT cyberJack RFID basis 1).
1562
2019-09-28 18:06:51,722+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_RECOGNIZED to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1563
2019-09-28 18:06:51,722+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_RECOGNIZED to EventCallback org.openecard.addon.EventHandler@ea6137.
1564
2019-09-28 18:06:51,722+02 [Recoginiton-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_RECOGNIZED to EventCallback org.openecard.richclient.gui.Status@f9c5b7.
1565
2019-09-28 18:06:51,723+02 [Dispatcher Event 0] INFO  o.o.c.sal.state.SALStateCallback:63 - Add ConnectionHandle to SAL:
1566
ConnectionHandle:
1567
  Session: C-AaenRmJCtZKKUzQvzqkw
1568
  ContextHandle: 8F27404E59BEC1306A299DCB3866A1D6
1569
  IFDName: REINER SCT cyberJack RFID basis 1  SlotIndex: 0
1570
  CardType: http://bsi.bund.de/cif/npa.xml
1571
2019-09-28 18:06:51,723+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:378 - Event: CARD_RECOGNIZED
1572
2019-09-28 18:06:51,723+02 [Dispatcher Event 0] DEBUG org.openecard.sal.SelectorSAL:185 - Looking up responsible SAL for handle with, ctx=8F27404E59BEC1306A299DCB3866A1D6, slot=null
1573
2019-09-28 18:06:51,723+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=REINER SCT cyberJack RFID basis 1, slot=null, ctx=8F27404E59BEC1306A299DCB3866A1D6
1574
2019-09-28 18:06:51,723+02 [Dispatcher Event 0] DEBUG org.openecard.sal.SelectorSAL:193 - Requesting CIF from CIF-Repo for type=http://bsi.bund.de/cif/npa.xml.
1575
2019-09-28 18:06:51,723+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:392 - RecognitionInfo: http://bsi.bund.de/cif/npa.xml, null
1576
2019-09-28 18:06:51,723+02 [Dispatcher Event 0] DEBUG o.o.r.staticrepo.LocalCifRepo:131 - Requesting CIFs with GetCardInfoOrACD call.
1577
2019-09-28 18:06:51,723+02 [Dispatcher Event 2] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
1578
2019-09-28 18:06:51,724+02 [Dispatcher Event 2] DEBUG org.openecard.sal.SelectorSAL:205 - Requesting CIF from CIF-Repo for type=http://bsi.bund.de/cif/npa.xml.
1579
2019-09-28 18:06:51,724+02 [Dispatcher Event 2] DEBUG o.o.r.staticrepo.LocalCifRepo:131 - Requesting CIFs with GetCardInfoOrACD call.
1580
2019-09-28 18:06:51,736+02 [Thread-9] DEBUG o.o.binding.tctoken.ResourceContext:246 - TLS handshake performed.
1581
2019-09-28 18:06:51,736+02 [Thread-9] INFO  o.o.common.util.TR03112Utils:107 - Checking certificate hash of https://de-mw.eid.digst.dk against list of communication certificates.
1582
2019-09-28 18:06:51,737+02 [Thread-9] DEBUG o.o.common.util.TR03112Utils:115 - Hash of the retrieved server certificate: 903BA9A1E626947DCF2134A82D4F48C082992003DCAC7D403D78C4D09440B8D4
1583
2019-09-28 18:06:51,738+02 [Thread-9] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 627DED65DF85F4445B4481374BDCA46708B094D30D1B0BA6759879BBC67F240E
1584
2019-09-28 18:06:51,738+02 [Thread-9] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 903BA9A1E626947DCF2134A82D4F48C082992003DCAC7D403D78C4D09440B8D4
1585
2019-09-28 18:06:51,739+02 [Thread-9] DEBUG o.o.common.util.TR03112Utils:61 - Checking SOP for https://de-mw.eid.digst.dk/eidas-middleware/ResponseSender?refID=460f2db4-cf73-4338-800a-ba53c82059da and https://de-mw.eid.digst.dk.
1586
2019-09-28 18:06:51,739+02 [Thread-9] INFO  o.o.c.t.ClientCertDefaultTlsClient:298 - TLS warning sent.
1587
2019-09-28 18:06:51,739+02 [Thread-9] INFO  o.o.c.t.ClientCertDefaultTlsClient:300 - TLS(WARN): Close [close_notify=0] --> Connection closed
1588
2019-09-28 18:06:51,740+02 [Thread-9] DEBUG o.o.binding.tctoken.TCTokenHandler:481 - Setting redirect address to 'https://de-mw.eid.digst.dk/eidas-middleware/ResponseSender?refID=460f2db4-cf73-4338-800a-ba53c82059da'.
1589
2019-09-28 18:06:51,742+02 [Thread-9] DEBUG org.openecard.common.DynamicContext:96 - Removing DynamicContext which contains 1 map entries.
1590
2019-09-28 18:06:51,742+02 [Thread-9] DEBUG o.o.c.b.h.h.HttpAppPluginActionHandler:211 - Recieved BindingResult with ResultCode REDIRECT
1591
2019-09-28 18:06:51,744+02 [Dispatcher Event 0] DEBUG o.o.r.staticrepo.LocalCifRepo:172 - Returning CIFs from GetCardInfoOrACD call.
1592
2019-09-28 18:06:51,744+02 [Thread-9] DEBUG o.o.c.b.h.h.HttpAppPluginActionHandler:200 - BindingResult contains no body.
1593
2019-09-28 18:06:51,744+02 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:94 - Add new entry to card states: CardStateEntry@3 {
1594
  handle=  ConnectionHandle {
1595
    ctx=8F27404E59BEC1306A299DCB3866A1D6
1596
    ifd=REINER SCT cyberJack RFID basis 1
1597
    idx=0
1598
    slot=null
1599
    app=3F00
1600
    Recognition {
1601
      typ=http://bsi.bund.de/cif/npa.xml
1602
      ident=null
1603
    }
1604
  }
1605
}
1606
2019-09-28 18:06:51,744+02 [Dispatcher Event 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification RECOGNIZED_CARD_ACTIVE to EventCallback org.openecard.common.sal.state.SALStateCallback@955596.
1607
2019-09-28 18:06:51,744+02 [Dispatcher Event 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification RECOGNIZED_CARD_ACTIVE to EventCallback org.openecard.addon.EventHandler@ea6137.
1608
2019-09-28 18:06:51,745+02 [Thread-9] DEBUG o.o.c.b.h.h.HttpAppPluginActionHandler:131 - HTTP response: HTTP/1.1 303  [Location: https://de-mw.eid.digst.dk/eidas-middleware/ResponseSender?ResultMajor=error&refID=460f2db4-cf73-4338-800a-ba53c82059da&ResultMinor=clientError] [Content-Type: text/plain; charset=UTF-8,Content-Length: 151,Chunked: false]
1609
2019-09-28 18:06:51,761+02 [Dispatcher Event 2] DEBUG o.o.r.staticrepo.LocalCifRepo:172 - Returning CIFs from GetCardInfoOrACD call.
1610
2019-09-28 18:06:58,573+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_WaitForSlotEvent: 0x00000000 -> CKR_OK, duration=28.685s
1611
2019-09-28 18:06:58,574+02 [MwEventManager] DEBUG o.o.mdlw.event.MwEventRunner:136 - Middleware event detected.
1612
2019-09-28 18:06:58,574+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetSlotList.
1613
2019-09-28 18:06:58,576+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetSlotList: 0x00000000 -> CKR_OK, duration=0.002s
1614
2019-09-28 18:06:58,576+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetSlotList.
1615
2019-09-28 18:06:58,578+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetSlotList: 0x00000000 -> CKR_OK, duration=0.002s
1616
2019-09-28 18:06:58,578+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetSlotInfo.
1617
2019-09-28 18:06:58,579+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetSlotInfo: 0x00000000 -> CKR_OK, duration=0.000s
1618
2019-09-28 18:06:58,579+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetSlotInfo.
1619
2019-09-28 18:06:58,579+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetSlotInfo: 0x00000000 -> CKR_OK, duration=0.000s
1620
2019-09-28 18:06:58,579+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetSlotInfo.
1621
2019-09-28 18:06:58,580+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetSlotInfo: 0x00000000 -> CKR_OK, duration=0.000s
1622
2019-09-28 18:06:58,580+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetSlotInfo.
1623
2019-09-28 18:06:58,581+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetSlotInfo: 0x00000000 -> CKR_OK, duration=0.000s
1624
2019-09-28 18:06:58,581+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetSlotInfo.
1625
2019-09-28 18:06:58,581+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetSlotInfo: 0x00000000 -> CKR_OK, duration=0.000s
1626
2019-09-28 18:06:58,581+02 [MwEventManager] DEBUG o.o.mdlw.event.MwEventRunner:146 - Slot event recognized, slotId=2, ifdName=DATEV Virtueller SmartCard Leser 0.
1627
2019-09-28 18:06:58,581+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_GetTokenInfo.
1628
2019-09-28 18:06:58,582+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:535 - Return code for C_GetTokenInfo: 0x000000e0 -> CKR_TOKEN_NOT_PRESENT, duration=0.001s
1629
2019-09-28 18:06:58,582+02 [MwEventManager] DEBUG o.o.mdlw.event.MwEventRunner:156 - Error requesting token information.
1630
org.openecard.mdlw.sal.exceptions.SessionException: [CKR_TOKEN_NOT_PRESENT] The token was not present in its slot at the time that the function was invoked.
1631
	at org.openecard.mdlw.sal.MiddleWareWrapper.raiseError(MiddleWareWrapper.java:604)
1632
	at org.openecard.mdlw.sal.MiddleWareWrapper.check(MiddleWareWrapper.java:540)
1633
	at org.openecard.mdlw.sal.MiddleWareWrapper.check(MiddleWareWrapper.java:545)
1634
	at org.openecard.mdlw.sal.MiddleWareWrapper.getTokenInfo(MiddleWareWrapper.java:283)
1635
	at org.openecard.mdlw.sal.MwSlot.getTokenInfo(MwSlot.java:72)
1636
	at org.openecard.mdlw.event.MwEventRunner.run(MwEventRunner.java:148)
1637
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
1638
	at java.util.concurrent.FutureTask.run(Unknown Source)
1639
	at java.lang.Thread.run(Unknown Source)
1640
2019-09-28 18:06:58,582+02 [MwEventManager] DEBUG o.o.mdlw.event.MwEventRunner:322 - Processing of already sent card removed event detected. Not sending event.
1641
2019-09-28 18:06:58,582+02 [MwEventManager] DEBUG o.o.mdlw.event.MwEventRunner:109 - Waiting for Middleware event.
1642
2019-09-28 18:06:58,583+02 [MwEventManager] DEBUG o.o.mdlw.sal.MiddleWareWrapper:526 - Executing function C_WaitForSlotEvent.
1643
2019-09-28 18:07:13,340+02 [AWT-EventQueue-0] DEBUG o.openecard.richclient.gui.Status$1:182 - Shutdown button pressed.
1644
2019-09-28 18:07:13,351+02 [AWT-EventQueue-0] DEBUG o.o.sal.protocol.eac.EACProtocol:71 - Destroying EAC protocol instance.
1645
2019-09-28 18:07:13,354+02 [IFD Watcher 0] WARN  org.openecard.ifd.scio.IFD:574 - Wait interrupted by another thread.
1646
java.lang.InterruptedException: null
1647
	at java.util.concurrent.FutureTask.awaitDone(Unknown Source)
1648
	at java.util.concurrent.FutureTask.get(Unknown Source)
1649
	at org.openecard.ifd.scio.IFD.wait(IFD.java:539)
1650
	at org.openecard.ifd.event.IfdEventManager.wait(IfdEventManager.java:122)
1651
	at org.openecard.ifd.event.IfdEventRunner.run(IfdEventRunner.java:130)
1652
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
1653
	at java.util.concurrent.FutureTask.run(Unknown Source)
1654
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
1655
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
1656
	at java.lang.Thread.run(Unknown Source)
1657
2019-09-28 18:07:13,354+02 [IFD Watcher 0] WARN  o.o.ifd.event.IfdEventRunner:134 - IFD Wait returned with error.
1658
org.openecard.common.WSHelper$WSException: http://www.bsi.bund.de/ecard/api/1.1/resultminor/ifdl#cancellationByUser
1659
  ==> Wait interrupted by another thread.
1660
	at org.openecard.common.ECardException.makeException(ECardException.java:64)
1661
	at org.openecard.common.WSHelper$WSException.<init>(WSHelper.java:47)
1662
	at org.openecard.common.WSHelper.checkResult(WSHelper.java:69)
1663
	at org.openecard.ifd.event.IfdEventManager.wait(IfdEventManager.java:125)
1664
	at org.openecard.ifd.event.IfdEventRunner.run(IfdEventRunner.java:130)
1665
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
1666
	at java.util.concurrent.FutureTask.run(Unknown Source)
1667
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
1668
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
1669
	at java.lang.Thread.run(Unknown Source)
1670
2019-09-28 18:07:13,355+02 [IFD Watcher 0] INFO  o.o.ifd.event.IfdEventRunner:142 - Event thread interrupted.
1671
java.lang.InterruptedException: sleep interrupted
1672
	at java.lang.Thread.sleep(Native Method)
1673
	at org.openecard.ifd.event.IfdEventRunner.run(IfdEventRunner.java:137)
1674
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
1675
	at java.util.concurrent.FutureTask.run(Unknown Source)
1676
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
1677
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
1678
	at java.lang.Thread.run(Unknown Source)
1679
2019-09-28 18:07:13,355+02 [IFD Watcher 0] INFO  o.o.ifd.event.IfdEventRunner:144 - Stopping IFD event thread.
(2-2/2)