Project

General

Profile

Feature #710 » richclient_info.log

Marko Preuss, 12/20/2018 09:07 PM

 
1
2018-12-20 21:00:44,967+01 [AWT-EventQueue-0] INFO  o.o.richclient.LogbackConfig:81 - Configured Logback with config file from: /home/lindsay/.openecard/richclient_logback.xml
2
2018-12-20 21:00:54,927+01 [SCIO Watcher 0] INFO  o.o.i.s.wrapper.SingleThreadChannel:139 - Card connected with protocol T=1.
3
2018-12-20 21:00:54,935+01 [IFD Watcher 0] DEBUG o.o.common.util.HandlerUtils:132 - Found ContextHandle in object of type GetIFDCapabilities.
4
2018-12-20 21:00:54,950+01 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
5
2018-12-20 21:00:54,950+01 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
6
2018-12-20 21:00:54,950+01 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
7
2018-12-20 21:00:54,951+01 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.GetIFDCapabilities
8
2018-12-20 21:00:54,952+01 [IFD Watcher 0] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'REINER SCT cyberJack RFID komfort (9394279424) 00 00' is already connected.
9
2018-12-20 21:00:54,990+01 [IFD Watcher 0] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
10
2018-12-20 21:00:54,990+01 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
11
2018-12-20 21:00:54,990+01 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
12
2018-12-20 21:00:54,991+01 [IFD Watcher 0] DEBUG o.o.ifd.event.IfdEventRunner:235 - Found a card insert event (REINER SCT cyberJack RFID komfort (9394279424) 00 00).
13
2018-12-20 21:00:54,993+01 [IFD Watcher 0] INFO  o.o.ifd.event.IfdEventRunner:236 - Card with ATR=3B8780018031B8738401E019 inserted.
14
2018-12-20 21:00:54,994+01 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_INSERTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
15
2018-12-20 21:00:54,999+01 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_INSERTED to EventCallback org.openecard.richclient.gui.Status@87a85e1.
16
2018-12-20 21:00:55,001+01 [Dispatcher Event 1] DEBUG org.openecard.richclient.gui.Status:378 - Event: CARD_INSERTED
17
2018-12-20 21:00:55,003+01 [Dispatcher Event 1] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=REINER SCT cyberJack RFID komfort (9394279424) 00 00, slot=null, ctx=72E59137FF7BAF326A55F2DC1982D331
18
2018-12-20 21:00:55,003+01 [Dispatcher Event 1] DEBUG org.openecard.richclient.gui.Status:392 - RecognitionInfo: http://bsi.bund.de/cif/unknown, 3B8780018031B8738401E019
19
2018-12-20 21:00:55,004+01 [Dispatcher Event 1] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
20
2018-12-20 21:00:55,008+01 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_INSERTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
21
2018-12-20 21:00:55,011+01 [IFD Watcher 0] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'REINER SCT cyberJack RFID komfort (9394279424) 00 00' is already connected.
22
2018-12-20 21:00:55,020+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:132 - Found ContextHandle in object of type Connect.
23
2018-12-20 21:00:55,029+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
24
2018-12-20 21:00:55,030+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
25
2018-12-20 21:00:55,030+01 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:201 - Detecting initial terminal status.
26
2018-12-20 21:00:55,033+01 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:205 - Terminal='REINER SCT cyberJack RFID komfort (9394279424) 00 00' cardPresent=true
27
2018-12-20 21:00:55,033+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
28
2018-12-20 21:00:55,033+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Connect
29
2018-12-20 21:00:55,034+01 [IFD Watcher 1] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'REINER SCT cyberJack RFID komfort (9394279424) 00 00' is already connected.
30
2018-12-20 21:00:55,063+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
31
2018-12-20 21:00:55,063+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
32
2018-12-20 21:00:55,065+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
33
2018-12-20 21:00:55,066+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type BeginTransaction.
34
2018-12-20 21:00:55,108+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
35
2018-12-20 21:00:55,113+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
36
2018-12-20 21:00:55,113+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
37
2018-12-20 21:00:55,114+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.BeginTransaction
38
2018-12-20 21:00:55,127+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
39
2018-12-20 21:00:55,127+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
40
2018-12-20 21:00:55,127+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
41
2018-12-20 21:00:55,128+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
42
2018-12-20 21:00:55,136+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
43
2018-12-20 21:00:55,137+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
44
2018-12-20 21:00:55,137+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
45
2018-12-20 21:00:55,137+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
46
2018-12-20 21:00:55,138+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
47
2018-12-20 21:00:55,173+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
48
2018-12-20 21:00:55,189+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
49
2018-12-20 21:00:55,190+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
50
2018-12-20 21:00:55,190+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
51
2018-12-20 21:00:55,190+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
52
2018-12-20 21:00:55,200+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
53
2018-12-20 21:00:55,200+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
54
2018-12-20 21:00:55,201+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
55
2018-12-20 21:00:55,201+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
56
2018-12-20 21:00:55,202+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C020003
57
2018-12-20 21:00:55,206+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6A82
58
2018-12-20 21:00:55,216+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
59
2018-12-20 21:00:55,217+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
60
2018-12-20 21:00:55,217+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
61
2018-12-20 21:00:55,217+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
62
2018-12-20 21:00:55,221+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
63
2018-12-20 21:00:55,221+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
64
2018-12-20 21:00:55,222+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
65
2018-12-20 21:00:55,222+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
66
2018-12-20 21:00:55,222+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
67
2018-12-20 21:00:55,228+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
68
2018-12-20 21:00:55,239+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
69
2018-12-20 21:00:55,240+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
70
2018-12-20 21:00:55,240+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
71
2018-12-20 21:00:55,240+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
72
2018-12-20 21:00:55,244+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
73
2018-12-20 21:00:55,244+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
74
2018-12-20 21:00:55,245+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
75
2018-12-20 21:00:55,245+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
76
2018-12-20 21:00:55,246+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C022F00
77
2018-12-20 21:00:55,252+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
78
2018-12-20 21:00:55,268+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
79
2018-12-20 21:00:55,269+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
80
2018-12-20 21:00:55,269+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
81
2018-12-20 21:00:55,270+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
82
2018-12-20 21:00:55,276+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
83
2018-12-20 21:00:55,276+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
84
2018-12-20 21:00:55,276+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
85
2018-12-20 21:00:55,276+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
86
2018-12-20 21:00:55,277+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00B20404FF
87
2018-12-20 21:00:55,280+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6D00
88
2018-12-20 21:00:55,299+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
89
2018-12-20 21:00:55,299+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
90
2018-12-20 21:00:55,300+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
91
2018-12-20 21:00:55,300+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
92
2018-12-20 21:00:55,312+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
93
2018-12-20 21:00:55,313+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
94
2018-12-20 21:00:55,313+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
95
2018-12-20 21:00:55,313+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
96
2018-12-20 21:00:55,314+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
97
2018-12-20 21:00:55,319+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
98
2018-12-20 21:00:55,331+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
99
2018-12-20 21:00:55,332+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
100
2018-12-20 21:00:55,332+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
101
2018-12-20 21:00:55,332+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
102
2018-12-20 21:00:55,335+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
103
2018-12-20 21:00:55,336+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
104
2018-12-20 21:00:55,336+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
105
2018-12-20 21:00:55,336+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
106
2018-12-20 21:00:55,338+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C022F00
107
2018-12-20 21:00:55,345+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
108
2018-12-20 21:00:55,364+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
109
2018-12-20 21:00:55,364+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
110
2018-12-20 21:00:55,367+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
111
2018-12-20 21:00:55,367+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
112
2018-12-20 21:00:55,370+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
113
2018-12-20 21:00:55,371+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
114
2018-12-20 21:00:55,371+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
115
2018-12-20 21:00:55,371+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
116
2018-12-20 21:00:55,372+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00B20304FF
117
2018-12-20 21:00:55,375+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6D00
118
2018-12-20 21:00:55,383+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
119
2018-12-20 21:00:55,383+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
120
2018-12-20 21:00:55,383+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
121
2018-12-20 21:00:55,384+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
122
2018-12-20 21:00:55,391+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
123
2018-12-20 21:00:55,391+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
124
2018-12-20 21:00:55,392+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
125
2018-12-20 21:00:55,392+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
126
2018-12-20 21:00:55,393+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4040C0FF04573744549442076657220312E30
127
2018-12-20 21:00:55,403+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6A82
128
2018-12-20 21:00:55,411+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
129
2018-12-20 21:00:55,411+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
130
2018-12-20 21:00:55,413+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
131
2018-12-20 21:00:55,413+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
132
2018-12-20 21:00:55,424+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
133
2018-12-20 21:00:55,424+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
134
2018-12-20 21:00:55,425+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
135
2018-12-20 21:00:55,425+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
136
2018-12-20 21:00:55,426+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4040C0FD23300000045737445494420763335
137
2018-12-20 21:00:55,434+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 6A82
138
2018-12-20 21:00:55,446+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
139
2018-12-20 21:00:55,446+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
140
2018-12-20 21:00:55,447+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
141
2018-12-20 21:00:55,448+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
142
2018-12-20 21:00:55,453+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
143
2018-12-20 21:00:55,458+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
144
2018-12-20 21:00:55,458+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
145
2018-12-20 21:00:55,458+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
146
2018-12-20 21:00:55,459+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
147
2018-12-20 21:00:55,467+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
148
2018-12-20 21:00:55,485+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
149
2018-12-20 21:00:55,485+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
150
2018-12-20 21:00:55,485+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
151
2018-12-20 21:00:55,485+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
152
2018-12-20 21:00:55,489+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
153
2018-12-20 21:00:55,490+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
154
2018-12-20 21:00:55,490+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
155
2018-12-20 21:00:55,491+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
156
2018-12-20 21:00:55,492+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4020C022F00
157
2018-12-20 21:00:55,499+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
158
2018-12-20 21:00:55,521+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
159
2018-12-20 21:00:55,521+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
160
2018-12-20 21:00:55,521+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
161
2018-12-20 21:00:55,522+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
162
2018-12-20 21:00:55,526+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
163
2018-12-20 21:00:55,526+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
164
2018-12-20 21:00:55,527+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
165
2018-12-20 21:00:55,527+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
166
2018-12-20 21:00:55,527+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00B00000FF
167
2018-12-20 21:00:55,537+01 [IFD Watcher 1] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 61324F0FE828BD080FA000000167455349474E500F434941207A752044462E655369676E5100730C4F0AA000000167455349474E61094F07A0000002471001610B4F09E80704007F00070302610C4F0AA000000167455349474E6282
168
2018-12-20 21:00:55,548+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
169
2018-12-20 21:00:55,548+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
170
2018-12-20 21:00:55,548+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
171
2018-12-20 21:00:55,549+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type EndTransaction.
172
2018-12-20 21:00:55,551+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
173
2018-12-20 21:00:55,552+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
174
2018-12-20 21:00:55,552+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
175
2018-12-20 21:00:55,552+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.EndTransaction
176
2018-12-20 21:00:55,574+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
177
2018-12-20 21:00:55,574+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
178
2018-12-20 21:00:55,574+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
179
2018-12-20 21:00:55,575+01 [IFD Watcher 1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Disconnect.
180
2018-12-20 21:00:55,579+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
181
2018-12-20 21:00:55,579+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
182
2018-12-20 21:00:55,579+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
183
2018-12-20 21:00:55,580+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Disconnect
184
2018-12-20 21:00:55,587+01 [IFD Watcher 1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
185
2018-12-20 21:00:55,596+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
186
2018-12-20 21:00:55,596+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
187
2018-12-20 21:00:55,596+01 [IFD Watcher 1] DEBUG org.openecard.ifd.event.Recognizer:60 - Found a recognized card event (REINER SCT cyberJack RFID komfort (9394279424) 00 00).
188
2018-12-20 21:00:55,596+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_RECOGNIZED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
189
2018-12-20 21:00:55,598+01 [Dispatcher Event 0] INFO  o.o.c.sal.state.SALStateCallback:63 - Add ConnectionHandle to SAL:
190
ConnectionHandle:
191
  Session: EjRS8YywdxcQWtM990olOw
192
  ContextHandle: 72E59137FF7BAF326A55F2DC1982D331
193
  IFDName: REINER SCT cyberJack RFID komfort (9394279424) 00 00  SlotIndex: 0
194
  CardType: http://bsi.bund.de/cif/npa.xml
195
2018-12-20 21:00:55,599+01 [Dispatcher Event 0] DEBUG org.openecard.sal.SelectorSAL:185 - Looking up responsible SAL for handle with, ctx=72E59137FF7BAF326A55F2DC1982D331, slot=null
196
2018-12-20 21:00:55,599+01 [Dispatcher Event 0] DEBUG org.openecard.sal.SelectorSAL:193 - Requesting CIF from CIF-Repo for type=http://bsi.bund.de/cif/npa.xml.
197
2018-12-20 21:00:55,599+01 [Dispatcher Event 0] DEBUG o.o.r.staticrepo.LocalCifRepo:131 - Requesting CIFs with GetCardInfoOrACD call.
198
2018-12-20 21:00:55,614+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_RECOGNIZED to EventCallback org.openecard.richclient.gui.Status@87a85e1.
199
2018-12-20 21:00:55,615+01 [Dispatcher Event 1] DEBUG org.openecard.richclient.gui.Status:378 - Event: CARD_RECOGNIZED
200
2018-12-20 21:00:55,616+01 [Dispatcher Event 1] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=REINER SCT cyberJack RFID komfort (9394279424) 00 00, slot=null, ctx=72E59137FF7BAF326A55F2DC1982D331
201
2018-12-20 21:00:55,616+01 [Dispatcher Event 1] DEBUG org.openecard.richclient.gui.Status:392 - RecognitionInfo: http://bsi.bund.de/cif/npa.xml, null
202
2018-12-20 21:00:55,616+01 [Dispatcher Event 1] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
203
2018-12-20 21:00:55,624+01 [IFD Watcher 1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_RECOGNIZED to EventCallback org.openecard.addon.EventHandler@7c469c48.
204
2018-12-20 21:00:55,666+01 [Dispatcher Event 1] DEBUG org.openecard.sal.SelectorSAL:205 - Requesting CIF from CIF-Repo for type=http://bsi.bund.de/cif/npa.xml.
205
2018-12-20 21:00:55,666+01 [Dispatcher Event 1] DEBUG o.o.r.staticrepo.LocalCifRepo:131 - Requesting CIFs with GetCardInfoOrACD call.
206
2018-12-20 21:00:55,761+01 [Dispatcher Event 0] DEBUG o.o.r.staticrepo.LocalCifRepo:172 - Returning CIFs from GetCardInfoOrACD call.
207
2018-12-20 21:00:55,771+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:94 - Add new entry to card states: CardStateEntry@0 {
208
  handle=  ConnectionHandle {
209
    ctx=72E59137FF7BAF326A55F2DC1982D331
210
    ifd=REINER SCT cyberJack RFID komfort (9394279424) 00 00
211
    idx=0
212
    slot=null
213
    app=3F00
214
    Recognition {
215
      typ=http://bsi.bund.de/cif/npa.xml
216
      ident=null
217
    }
218
  }
219
}
220
2018-12-20 21:00:55,772+01 [Dispatcher Event 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification RECOGNIZED_CARD_ACTIVE to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
221
2018-12-20 21:00:55,773+01 [Dispatcher Event 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification RECOGNIZED_CARD_ACTIVE to EventCallback org.openecard.addon.EventHandler@7c469c48.
222
2018-12-20 21:00:55,851+01 [Dispatcher Event 1] DEBUG o.o.r.staticrepo.LocalCifRepo:172 - Returning CIFs from GetCardInfoOrACD call.
223
2018-12-20 21:02:16,424+01 [Thread-7] DEBUG o.o.c.b.h.h.HttpAppPluginActionHandler:88 - HTTP request: GET /eID-Client?tcTokenURL=https%3A%2F%2Fwww.fuehrungszeugnis.bund.de%2Fffw%2Fnpa-servlet%2F_FcslZNAQAKU80PqnEi3UQ%2FclientInvocation%3Bjsessionid%3D2C03384CF32556E0AA74287E034FC7E8.nodevlp61081-02 [Host: 127.0.0.1:24727, User-Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:64.0) Gecko/20100101 Firefox/64.0, Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8, Accept-Language: de,en-US;q=0.7,en;q=0.3, Accept-Encoding: gzip, deflate, Connection: keep-alive, Upgrade-Insecure-Requests: 1]
224
2018-12-20 21:02:16,447+01 [Thread-7] WARN  org.openecard.common.I18n:152 - Failed to load resource tr03112 for lang de_DE.
225
2018-12-20 21:02:16,465+01 [Thread-7] WARN  org.openecard.common.I18n:152 - Failed to load resource tctoken for lang de_DE.
226
2018-12-20 21:02:16,468+01 [Thread-7] WARN  org.openecard.common.I18n:152 - Failed to load resource pinplugin for lang de_DE.
227
2018-12-20 21:02:16,489+01 [Thread-7] WARN  org.openecard.common.I18n:152 - Failed to load resource pace for lang de_DE.
228
2018-12-20 21:02:16,501+01 [FuturePromise-3] WARN  o.o.common.util.JAXPSchemaValidator:143 - Did not find a default SchemaFactory.
229
2018-12-20 21:02:16,611+01 [Thread-7] DEBUG org.openecard.sal.SelectorSAL:205 - Requesting CIF from CIF-Repo for type=http://bsi.bund.de/cif/npa.xml.
230
2018-12-20 21:02:16,611+01 [Thread-7] DEBUG o.o.r.staticrepo.LocalCifRepo:131 - Requesting CIFs with GetCardInfoOrACD call.
231
2018-12-20 21:02:16,742+01 [Thread-7] DEBUG o.o.r.staticrepo.LocalCifRepo:172 - Returning CIFs from GetCardInfoOrACD call.
232
2018-12-20 21:02:16,801+01 [Thread-7] INFO  o.o.binding.tctoken.ResourceContext:207 - Trying to load resource from: https://www.fuehrungszeugnis.bund.de/ffw/npa-servlet/_FcslZNAQAKU80PqnEi3UQ/clientInvocation;jsessionid=2C03384CF32556E0AA74287E034FC7E8.nodevlp61081-02
233
2018-12-20 21:02:17,083+01 [Thread-7] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for java. Trying next one.
234
2018-12-20 21:02:17,130+01 [Thread-7] DEBUG o.o.c.t.proxy.ProxySettingsLoader$1:80 - Firefox settings folder is {0}
235
2018-12-20 21:02:17,134+01 [Thread-7] WARN  o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found.
236
2018-12-20 21:02:17,134+01 [Thread-7] WARN  o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found.
237
2018-12-20 21:02:17,134+01 [Thread-7] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for firefox. Trying next one.
238
2018-12-20 21:02:17,135+01 [Thread-7] WARN  o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found.
239
2018-12-20 21:02:17,135+01 [Thread-7] WARN  o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found.
240
2018-12-20 21:02:17,135+01 [Thread-7] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for desktop. Trying next one.
241
2018-12-20 21:02:17,139+01 [Thread-7] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for env. Trying next one.
242
2018-12-20 21:02:17,141+01 [Thread-7] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for java. Trying next one.
243
2018-12-20 21:02:17,148+01 [Thread-7] DEBUG o.o.c.t.proxy.ProxySettingsLoader$1:80 - Firefox settings folder is {0}
244
2018-12-20 21:02:17,148+01 [Thread-7] WARN  o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found.
245
2018-12-20 21:02:17,149+01 [Thread-7] WARN  o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found.
246
2018-12-20 21:02:17,149+01 [Thread-7] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for firefox. Trying next one.
247
2018-12-20 21:02:17,149+01 [Thread-7] WARN  o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found.
248
2018-12-20 21:02:17,149+01 [Thread-7] WARN  o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found.
249
2018-12-20 21:02:17,150+01 [Thread-7] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for desktop. Trying next one.
250
2018-12-20 21:02:17,150+01 [Thread-7] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for env. Trying next one.
251
2018-12-20 21:02:17,158+01 [Thread-7] DEBUG o.o.crypto.tls.proxy.ProxySettings:133 - Selecting proxy: DIRECT
252
2018-12-20 21:02:17,159+01 [Thread-7] DEBUG o.o.crypto.tls.proxy.ProxySettings:168 - Using proxy (DIRECT) to obtain socket.
253
2018-12-20 21:02:17,796+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:244 - Performing TLS handshake.
254
2018-12-20 21:02:18,600+01 [Thread-7] DEBUG o.o.c.tls.verify.HostnameVerifier:126 - Comparing connection hostname against certificate hostname: [www.fuehrungszeugnis.bund.de] [www.fuehrungszeugnis.bund.de]
255
2018-12-20 21:02:20,262+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:246 - TLS handshake performed.
256
2018-12-20 21:02:20,274+01 [Thread-7] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request:
257
  GET /ffw/npa-servlet/_FcslZNAQAKU80PqnEi3UQ/clientInvocation;jsessionid=2C03384CF32556E0AA74287E034FC7E8.nodevlp61081-02 HTTP/1.1
258
  Connection: keep-alive
259
  User-Agent: Open eCard App/1.3.0
260
  Host: www.fuehrungszeugnis.bund.de
261
  Accept: text/xml, */*;q=0.8
262
  Accept-Charset: utf-8, *;q=0.8
263

    
264
2018-12-20 21:02:20,275+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:267 - Sending HTTP request.
265
2018-12-20 21:02:20,969+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:270 - HTTP response received.
266
2018-12-20 21:02:20,973+01 [Thread-7] DEBUG o.o.transport.httpcore.HttpUtils:112 - HTTP Response:
267
  HTTP/1.1 302 Found
268
  Date: Thu, 20 Dec 2018 20:01:29 GMT
269
  Server: Apache
270
  Content-Length: 0
271
  Strict-Transport-Security: max-age=63072000;
272
  Cache-Control: no-cache, no-store
273
  Strict-Transport-Security: max-age=31536000
274
  Location: https://eid1.eid-service.de:443/gov_autent/async?SAMLRequest=xVfHlqtIEt3PV9RRLzlVeIFqXtUchBFGWGG16YNJjLDCSKCvH%2BqZ7veme3q6ezMbFknGjRtxL5Hkp3%2FNdfV0A%2F1QtM3bBn1BNk%2BgidukaLK3jWMLz%2FTmX%2B%2F%2F%2BDSEdYV1r8w05o0FrhMYxidmGEA%2FrnFs2wxTDfoT6G9FDBzr%2BLbJx7EbXmH4fr%2B%2FpBPI%2B6nJhgeYsqYYXqKpSV4SAKfpHW668HnFuVVghH8W4qE6a4zJKA6NGNeGL3DHhD9eg94CQ7cmAv%2B8DGD4oFskbxiL4DhNsAKOkeSWRxiGIjCa4hGcEFiKp1%2BaNgG3qtuiCI0%2BI9jmiVuZF004fi73G0lQJOjL%2BvhMZK1g5fZKEDictbefw2kEzQiHw9LEmyeh7WPwuQtvm7GfwOZJ4t42P9N0vI1wlKaiKI3ILYbgJE3tEJrcxiRNIuS6bTDClfUNvG3SsBo%2BAodhAlIzjGEzvm0wBKWfUewZQ2wMeUWwV5R82W13582T0bdjG7fVvmi%2BqDL1zWsbDsXw2oQ1GF7H%2BPXEqMdX7AV5jb5sGl5F2zaeLZAUPYjHzZP7TWHsQ%2BFV82Z4%2FaLpH%2BN1X5Nv3r9Y4PUz6%2F57hD8GCL%2BZZPP%2BZy3xCf4%2B1fs37%2FHzKsRHEcP7p1WrV76J%2B6UbQfK9KX%2FZ9JXhuvGLzGveaCh%2BSQMkDl5rmlev%2FwrEhWP4ZC8d%2BCXkg%2Bodf2n7DMYQBIURAl5x16Cf%2BArUqy%2B%2B9fID6E9E%2FUfKlacKxrxNnpgqa%2FtizOs%2FARKCAcXo5ziK%2F2p2%2BP1TMrwqYJGatP0amwz%2FJRKBkd1HZDIU2U%2B%2F6dUK8n8ovR%2FC5zYE3XOdpWi3%2BVwOV2Sr8H8S7IeihjxEN3%2BtDWsH4d8t42t1bNHloP8w0g8LblhN4D3ymRKuXA9gO9e3uT7qOW0PyDoswj0SOIZ921LCoz7QxiLiWYKQTXmggM5BD7s7xjzezbg5zrpDHlqOEfbyPOlGxQ2ZnrPN4zDGhhEst1mW1OmKBHqq35okrc%2FNpJjY%2FSE59NA%2BBoJ3tJulF5JWEtlFlFTuXA6jp8k5mj1CqzCN%2FJBCJi5ovgyHlYqqln%2BoL5eM8dybYef6VvTAvD%2BlIUD3VnIO4f0%2BqlMe73dZ5oBYYxEPiiO6yJrtpXEdBuUWkUWXccjsgnPq%2BMZWboBE%2FQCqrRgJnVUz7k4P%2BUuYaQQhkqpLyYriMBiiZzPlRxmYW%2BGEDcE4d6pGWUE4mhe%2FY70Ohdi7ZzBvb18l%2Bb7VPyx9kQP%2BjYHXtV8%2Fh98I%2BPfs%2FT2J7dQeIsNFJYMyeUik5xiH0OB4Y5XOmKhHn8r9kc%2BjO%2BmdaNPV7jWoXEiyYwzIk5aAh5w%2BSOJECMuN5x6ReNBigoTv8DZljT1bjNYWk0B9PPNqM0qsbvUaFSZ2gd8v%2BCl2PZ8Zu%2F110CJ8EKIOXA9ogbVla1yjrUuomp17iXMfztvyPjVIOrLOHh170qtxS5mDioGbMQ1L44HK2UOsD%2BX%2BSEbcUfHwR3ILCefuQCBK0qHwK1PUDzZodLks%2FAmT9wSKDr4zCrXb2OQ5cKOZe1i33VGw7G4OLqESb80hCQ55xnWJvhUM50ijV%2BYQFXFR4NfMVCzjCCHCwF%2FoaynHPGdEMYTlCxKNthiK0DYhIxQxdyaUJniGs%2BzSWeUF7GgAs0apx0ucDcOliSuKKi49iomte63qFjV8ud3bjtlIXbBfRIO%2BxkeChogUxYzwji3W1HgJjuFLypGU7AWHPU5Zw7b0DazOi7FXSvhwuAZNHjRMey6QhYgU3vTDM0WMxYWFpFrKe2VAlTFRyZ2sz704nPbGfRIC%2BYZMd%2B4q3%2FKsCjgCOXlOH%2BH3%2B0msjhhVgtvoGGf5Sjh%2BesapbuvYMx3uqcJjRxBYJI%2FrWkNBo5jtIOak%2BoeULlQCKMcp6VSRVQ84wwgwj4q%2BX5oRTNqOmoII2l6OulrSRSS2XqUR9cIOfiFXSYLul6Qq3SKgENxhSl1Ep7a4RWRS5ERWTN7jzpZjfMGP4nFPwNui7fx0jid5PXq20RjPHNM72tE6nTmqD0KGYvSTgGDCQyjEdTrJ3BaBh0EpilSmCvhGUSXbsTf6hlxo%2FT5phFalDYtDQzAQByRqvHHvca7gTbKsIDkOUaWESjZK2GHQ8wxldW56j%2Fr2QplJoHtL4g1xUMSPIE%2FKVr%2B4sosllQWEy308XpiqmmrGaZg7XO06pffN%2B%2BIX2jqzMJvqTfLBXxt84jLNzwYf5%2FMl66jm7B1RA1CiGgxKnE97e09TY2PVrV08%2BIugWSXUSKnJcF2B8mL2uOxypeeBukg%2BROgcqWhseLNS1rQTugtcVivrKg%2FdruhK4tHLeSsH%2FFKmW2vm1egw%2By4quFhxDaN%2BN0kSs1zhNY%2BoRq6xy8zSOHRHrFQrrtUtZIfsr%2Fl09WRUbvqhxylhJ818vF%2BsQhzlgILmkoYvu2MGnQafwWZSNdMSyw9eEaohmXoxmhDo%2Butq3OVdZ%2Fo6ethXp8VUDrHqBXF4WiIXY8l2lnQh0sjdfgoVEjbDbp2B6X4bpL22vZ5AiXQGl0VusLji5Gs2w%2FVIjXsOBWszwp8Fah%2Bru%2FwMVMtTHcUSpVben%2Bk%2Bu14DNDSQSU%2FEI5QcTaFSRy6WOCqm0UyaWoNm96ReLscj6nNrQwSHbzH2ckpRC5cHXO%2FU%2BtDER7SeF%2F6CnCEdr6zlPLIRVSyirFq4fZOQ6aFM2izcMUye4aZ3Z93mk5PqCQJ%2F8qyiL5sGMz38egfQCW5Ogs2LDT9y3g4RHiKiTxr%2FWPxLniUB6DGktK7mNjwqy5hfQ2syE%2FGEy9IsETMLT2KemRfaqB1JiW8OG%2FKLRmI%2BFnLlNFulnquLIxI6VPvULnCDk7YoBqyyvKvgMyKdkUo7KpLjr3O%2BumDbKhgpETvpcO53VObs%2BABW%2Bse8NBXdYUSsQIy%2FFJaFW5Olw1Z4jzNRTE3fZiL1NuQDrEJnFygObw5nkz3uC%2Fq6jFU39Yrj0oUmiaCHbEnrFi736JZqPFYpDFLdQSMfLRcrX6d2a96AJ2x1DwStum3xm0eX2OwfEA5w2AH3aumQ%2Bw9xgLhrWo9uyRaOh3rKQzq5B%2FQygwtz3YmXRXb1adLVvLBm4t7Ofdjo%2BhE6t%2FU8hVDuU0Gd2lsC3gfMsHNtMwTL1skxMiv34wphB4vC4TVCx%2BxMS8eDRaczzRRJ3%2Fytc%2F3r4v%2B%2BIbx%2FvWf8eLOAf%2Bem%2B%2F5v&Signature=imoCHv%2B9tiVuA5izEjBxSh63f8cE8aBQkBtwljdEV2AMz%2FZs7NLRJgB%2BmEAnDvtEd2qgLYyn38bB0h4RXkxW5x4QpWqW4Kv%2BNpNQ5M4RpQKb8AGK7iHVvmFEt8FcELtlR7YxNkESnw9Eq6xHwGvX8QJhNNU6g6suvOOz1lhl0aSb2sej%2BZlFSl%2F%2FCP7c06EPpGwK%2FMVsCC5SL6iTeVCaOq%2BdVDKVsF9uzUg1iLDe7%2F3zU%2FfTLhSUutBH%2FJShWV6p%2BF3TSriN7g60FERh5VmaVZF1Ps31hjrR2IIb%2FanqtwmuP0DhpxC7%2BG1Ue9PyCy6RTMsuXHcBIOslNTt1rB%2FAGg%3D%3D&SigAlg=http%3A%2F%2Fwww.w3.org%2F2000%2F09%2Fxmldsig%23rsa-sha1
275
  X-Frame-Options: SAMEORIGIN
276
  public-key-pins: pin-sha256="4guwnULJHWC2d8AOjHNy9ePbLNgKj8xZsChBUeAkVVM="; pin-sha256="RkrzVSUw6JIwnLAtTBiUfFTdzJSziIvz4gbKx0Yu694="; max-age=15552000
277
  Keep-Alive: timeout=10, max=500
278
  Connection: Keep-Alive
279
  Content-Type: text/plain
280

    
281

    
282
2018-12-20 21:02:20,975+01 [Thread-7] INFO  o.o.c.t.ClientCertDefaultTlsClient:298 - TLS warning sent.
283
2018-12-20 21:02:20,976+01 [Thread-7] INFO  o.o.c.t.ClientCertDefaultTlsClient:300 - TLS(WARN): Close [close_notify=0] --> Connection closed
284
2018-12-20 21:02:20,977+01 [Thread-7] INFO  o.o.binding.tctoken.ResourceContext:207 - Trying to load resource from: https://eid1.eid-service.de:443/gov_autent/async?SAMLRequest=xVfHlqtIEt3PV9RRLzlVeIFqXtUchBFGWGG16YNJjLDCSKCvH%2BqZ7veme3q6ezMbFknGjRtxL5Hkp3%2FNdfV0A%2F1QtM3bBn1BNk%2BgidukaLK3jWMLz%2FTmX%2B%2F%2F%2BDSEdYV1r8w05o0FrhMYxidmGEA%2FrnFs2wxTDfoT6G9FDBzr%2BLbJx7EbXmH4fr%2B%2FpBPI%2B6nJhgeYsqYYXqKpSV4SAKfpHW668HnFuVVghH8W4qE6a4zJKA6NGNeGL3DHhD9eg94CQ7cmAv%2B8DGD4oFskbxiL4DhNsAKOkeSWRxiGIjCa4hGcEFiKp1%2BaNgG3qtuiCI0%2BI9jmiVuZF004fi73G0lQJOjL%2BvhMZK1g5fZKEDictbefw2kEzQiHw9LEmyeh7WPwuQtvm7GfwOZJ4t42P9N0vI1wlKaiKI3ILYbgJE3tEJrcxiRNIuS6bTDClfUNvG3SsBo%2BAodhAlIzjGEzvm0wBKWfUewZQ2wMeUWwV5R82W13582T0bdjG7fVvmi%2BqDL1zWsbDsXw2oQ1GF7H%2BPXEqMdX7AV5jb5sGl5F2zaeLZAUPYjHzZP7TWHsQ%2BFV82Z4%2FaLpH%2BN1X5Nv3r9Y4PUz6%2F57hD8GCL%2BZZPP%2BZy3xCf4%2B1fs37%2FHzKsRHEcP7p1WrV76J%2B6UbQfK9KX%2FZ9JXhuvGLzGveaCh%2BSQMkDl5rmlev%2FwrEhWP4ZC8d%2BCXkg%2Bodf2n7DMYQBIURAl5x16Cf%2BArUqy%2B%2B9fID6E9E%2FUfKlacKxrxNnpgqa%2FtizOs%2FARKCAcXo5ziK%2F2p2%2BP1TMrwqYJGatP0amwz%2FJRKBkd1HZDIU2U%2B%2F6dUK8n8ovR%2FC5zYE3XOdpWi3%2BVwOV2Sr8H8S7IeihjxEN3%2BtDWsH4d8t42t1bNHloP8w0g8LblhN4D3ymRKuXA9gO9e3uT7qOW0PyDoswj0SOIZ921LCoz7QxiLiWYKQTXmggM5BD7s7xjzezbg5zrpDHlqOEfbyPOlGxQ2ZnrPN4zDGhhEst1mW1OmKBHqq35okrc%2FNpJjY%2FSE59NA%2BBoJ3tJulF5JWEtlFlFTuXA6jp8k5mj1CqzCN%2FJBCJi5ovgyHlYqqln%2BoL5eM8dybYef6VvTAvD%2BlIUD3VnIO4f0%2BqlMe73dZ5oBYYxEPiiO6yJrtpXEdBuUWkUWXccjsgnPq%2BMZWboBE%2FQCqrRgJnVUz7k4P%2BUuYaQQhkqpLyYriMBiiZzPlRxmYW%2BGEDcE4d6pGWUE4mhe%2FY70Ohdi7ZzBvb18l%2Bb7VPyx9kQP%2BjYHXtV8%2Fh98I%2BPfs%2FT2J7dQeIsNFJYMyeUik5xiH0OB4Y5XOmKhHn8r9kc%2BjO%2BmdaNPV7jWoXEiyYwzIk5aAh5w%2BSOJECMuN5x6ReNBigoTv8DZljT1bjNYWk0B9PPNqM0qsbvUaFSZ2gd8v%2BCl2PZ8Zu%2F110CJ8EKIOXA9ogbVla1yjrUuomp17iXMfztvyPjVIOrLOHh170qtxS5mDioGbMQ1L44HK2UOsD%2BX%2BSEbcUfHwR3ILCefuQCBK0qHwK1PUDzZodLks%2FAmT9wSKDr4zCrXb2OQ5cKOZe1i33VGw7G4OLqESb80hCQ55xnWJvhUM50ijV%2BYQFXFR4NfMVCzjCCHCwF%2FoaynHPGdEMYTlCxKNthiK0DYhIxQxdyaUJniGs%2BzSWeUF7GgAs0apx0ucDcOliSuKKi49iomte63qFjV8ud3bjtlIXbBfRIO%2BxkeChogUxYzwji3W1HgJjuFLypGU7AWHPU5Zw7b0DazOi7FXSvhwuAZNHjRMey6QhYgU3vTDM0WMxYWFpFrKe2VAlTFRyZ2sz704nPbGfRIC%2BYZMd%2B4q3%2FKsCjgCOXlOH%2BH3%2B0msjhhVgtvoGGf5Sjh%2BesapbuvYMx3uqcJjRxBYJI%2FrWkNBo5jtIOak%2BoeULlQCKMcp6VSRVQ84wwgwj4q%2BX5oRTNqOmoII2l6OulrSRSS2XqUR9cIOfiFXSYLul6Qq3SKgENxhSl1Ep7a4RWRS5ERWTN7jzpZjfMGP4nFPwNui7fx0jid5PXq20RjPHNM72tE6nTmqD0KGYvSTgGDCQyjEdTrJ3BaBh0EpilSmCvhGUSXbsTf6hlxo%2FT5phFalDYtDQzAQByRqvHHvca7gTbKsIDkOUaWESjZK2GHQ8wxldW56j%2Fr2QplJoHtL4g1xUMSPIE%2FKVr%2B4sosllQWEy308XpiqmmrGaZg7XO06pffN%2B%2BIX2jqzMJvqTfLBXxt84jLNzwYf5%2FMl66jm7B1RA1CiGgxKnE97e09TY2PVrV08%2BIugWSXUSKnJcF2B8mL2uOxypeeBukg%2BROgcqWhseLNS1rQTugtcVivrKg%2FdruhK4tHLeSsH%2FFKmW2vm1egw%2By4quFhxDaN%2BN0kSs1zhNY%2BoRq6xy8zSOHRHrFQrrtUtZIfsr%2Fl09WRUbvqhxylhJ818vF%2BsQhzlgILmkoYvu2MGnQafwWZSNdMSyw9eEaohmXoxmhDo%2Butq3OVdZ%2Fo6ethXp8VUDrHqBXF4WiIXY8l2lnQh0sjdfgoVEjbDbp2B6X4bpL22vZ5AiXQGl0VusLji5Gs2w%2FVIjXsOBWszwp8Fah%2Bru%2FwMVMtTHcUSpVben%2Bk%2Bu14DNDSQSU%2FEI5QcTaFSRy6WOCqm0UyaWoNm96ReLscj6nNrQwSHbzH2ckpRC5cHXO%2FU%2BtDER7SeF%2F6CnCEdr6zlPLIRVSyirFq4fZOQ6aFM2izcMUye4aZ3Z93mk5PqCQJ%2F8qyiL5sGMz38egfQCW5Ogs2LDT9y3g4RHiKiTxr%2FWPxLniUB6DGktK7mNjwqy5hfQ2syE%2FGEy9IsETMLT2KemRfaqB1JiW8OG%2FKLRmI%2BFnLlNFulnquLIxI6VPvULnCDk7YoBqyyvKvgMyKdkUo7KpLjr3O%2BumDbKhgpETvpcO53VObs%2BABW%2Bse8NBXdYUSsQIy%2FFJaFW5Olw1Z4jzNRTE3fZiL1NuQDrEJnFygObw5nkz3uC%2Fq6jFU39Yrj0oUmiaCHbEnrFi736JZqPFYpDFLdQSMfLRcrX6d2a96AJ2x1DwStum3xm0eX2OwfEA5w2AH3aumQ%2Bw9xgLhrWo9uyRaOh3rKQzq5B%2FQygwtz3YmXRXb1adLVvLBm4t7Ofdjo%2BhE6t%2FU8hVDuU0Gd2lsC3gfMsHNtMwTL1skxMiv34wphB4vC4TVCx%2BxMS8eDRaczzRRJ3%2Fytc%2F3r4v%2B%2BIbx%2FvWf8eLOAf%2Bem%2B%2F5v&Signature=imoCHv%2B9tiVuA5izEjBxSh63f8cE8aBQkBtwljdEV2AMz%2FZs7NLRJgB%2BmEAnDvtEd2qgLYyn38bB0h4RXkxW5x4QpWqW4Kv%2BNpNQ5M4RpQKb8AGK7iHVvmFEt8FcELtlR7YxNkESnw9Eq6xHwGvX8QJhNNU6g6suvOOz1lhl0aSb2sej%2BZlFSl%2F%2FCP7c06EPpGwK%2FMVsCC5SL6iTeVCaOq%2BdVDKVsF9uzUg1iLDe7%2F3zU%2FfTLhSUutBH%2FJShWV6p%2BF3TSriN7g60FERh5VmaVZF1Ps31hjrR2IIb%2FanqtwmuP0DhpxC7%2BG1Ue9PyCy6RTMsuXHcBIOslNTt1rB%2FAGg%3D%3D&SigAlg=http%3A%2F%2Fwww.w3.org%2F2000%2F09%2Fxmldsig%23rsa-sha1
285
2018-12-20 21:02:20,977+01 [Thread-7] DEBUG o.o.crypto.tls.proxy.ProxySettings:133 - Selecting proxy: DIRECT
286
2018-12-20 21:02:20,977+01 [Thread-7] DEBUG o.o.crypto.tls.proxy.ProxySettings:168 - Using proxy (DIRECT) to obtain socket.
287
2018-12-20 21:02:22,455+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:244 - Performing TLS handshake.
288
2018-12-20 21:02:23,067+01 [Thread-7] DEBUG o.o.c.tls.verify.HostnameVerifier:126 - Comparing connection hostname against certificate hostname: [eid1.eid-service.de] [eid1.eid-service.de]
289
2018-12-20 21:02:23,969+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:246 - TLS handshake performed.
290
2018-12-20 21:02:23,972+01 [Thread-7] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request:
291
  GET /gov_autent/async?SAMLRequest=xVfHlqtIEt3PV9RRLzlVeIFqXtUchBFGWGG16YNJjLDCSKCvH%2BqZ7veme3q6ezMbFknGjRtxL5Hkp3%2FNdfV0A%2F1QtM3bBn1BNk%2BgidukaLK3jWMLz%2FTmX%2B%2F%2F%2BDSEdYV1r8w05o0FrhMYxidmGEA%2FrnFs2wxTDfoT6G9FDBzr%2BLbJx7EbXmH4fr%2B%2FpBPI%2B6nJhgeYsqYYXqKpSV4SAKfpHW668HnFuVVghH8W4qE6a4zJKA6NGNeGL3DHhD9eg94CQ7cmAv%2B8DGD4oFskbxiL4DhNsAKOkeSWRxiGIjCa4hGcEFiKp1%2BaNgG3qtuiCI0%2BI9jmiVuZF004fi73G0lQJOjL%2BvhMZK1g5fZKEDictbefw2kEzQiHw9LEmyeh7WPwuQtvm7GfwOZJ4t42P9N0vI1wlKaiKI3ILYbgJE3tEJrcxiRNIuS6bTDClfUNvG3SsBo%2BAodhAlIzjGEzvm0wBKWfUewZQ2wMeUWwV5R82W13582T0bdjG7fVvmi%2BqDL1zWsbDsXw2oQ1GF7H%2BPXEqMdX7AV5jb5sGl5F2zaeLZAUPYjHzZP7TWHsQ%2BFV82Z4%2FaLpH%2BN1X5Nv3r9Y4PUz6%2F57hD8GCL%2BZZPP%2BZy3xCf4%2B1fs37%2FHzKsRHEcP7p1WrV76J%2B6UbQfK9KX%2FZ9JXhuvGLzGveaCh%2BSQMkDl5rmlev%2FwrEhWP4ZC8d%2BCXkg%2Bodf2n7DMYQBIURAl5x16Cf%2BArUqy%2B%2B9fID6E9E%2FUfKlacKxrxNnpgqa%2FtizOs%2FARKCAcXo5ziK%2F2p2%2BP1TMrwqYJGatP0amwz%2FJRKBkd1HZDIU2U%2B%2F6dUK8n8ovR%2FC5zYE3XOdpWi3%2BVwOV2Sr8H8S7IeihjxEN3%2BtDWsH4d8t42t1bNHloP8w0g8LblhN4D3ymRKuXA9gO9e3uT7qOW0PyDoswj0SOIZ921LCoz7QxiLiWYKQTXmggM5BD7s7xjzezbg5zrpDHlqOEfbyPOlGxQ2ZnrPN4zDGhhEst1mW1OmKBHqq35okrc%2FNpJjY%2FSE59NA%2BBoJ3tJulF5JWEtlFlFTuXA6jp8k5mj1CqzCN%2FJBCJi5ovgyHlYqqln%2BoL5eM8dybYef6VvTAvD%2BlIUD3VnIO4f0%2BqlMe73dZ5oBYYxEPiiO6yJrtpXEdBuUWkUWXccjsgnPq%2BMZWboBE%2FQCqrRgJnVUz7k4P%2BUuYaQQhkqpLyYriMBiiZzPlRxmYW%2BGEDcE4d6pGWUE4mhe%2FY70Ohdi7ZzBvb18l%2Bb7VPyx9kQP%2BjYHXtV8%2Fh98I%2BPfs%2FT2J7dQeIsNFJYMyeUik5xiH0OB4Y5XOmKhHn8r9kc%2BjO%2BmdaNPV7jWoXEiyYwzIk5aAh5w%2BSOJECMuN5x6ReNBigoTv8DZljT1bjNYWk0B9PPNqM0qsbvUaFSZ2gd8v%2BCl2PZ8Zu%2F110CJ8EKIOXA9ogbVla1yjrUuomp17iXMfztvyPjVIOrLOHh170qtxS5mDioGbMQ1L44HK2UOsD%2BX%2BSEbcUfHwR3ILCefuQCBK0qHwK1PUDzZodLks%2FAmT9wSKDr4zCrXb2OQ5cKOZe1i33VGw7G4OLqESb80hCQ55xnWJvhUM50ijV%2BYQFXFR4NfMVCzjCCHCwF%2FoaynHPGdEMYTlCxKNthiK0DYhIxQxdyaUJniGs%2BzSWeUF7GgAs0apx0ucDcOliSuKKi49iomte63qFjV8ud3bjtlIXbBfRIO%2BxkeChogUxYzwji3W1HgJjuFLypGU7AWHPU5Zw7b0DazOi7FXSvhwuAZNHjRMey6QhYgU3vTDM0WMxYWFpFrKe2VAlTFRyZ2sz704nPbGfRIC%2BYZMd%2B4q3%2FKsCjgCOXlOH%2BH3%2B0msjhhVgtvoGGf5Sjh%2BesapbuvYMx3uqcJjRxBYJI%2FrWkNBo5jtIOak%2BoeULlQCKMcp6VSRVQ84wwgwj4q%2BX5oRTNqOmoII2l6OulrSRSS2XqUR9cIOfiFXSYLul6Qq3SKgENxhSl1Ep7a4RWRS5ERWTN7jzpZjfMGP4nFPwNui7fx0jid5PXq20RjPHNM72tE6nTmqD0KGYvSTgGDCQyjEdTrJ3BaBh0EpilSmCvhGUSXbsTf6hlxo%2FT5phFalDYtDQzAQByRqvHHvca7gTbKsIDkOUaWESjZK2GHQ8wxldW56j%2Fr2QplJoHtL4g1xUMSPIE%2FKVr%2B4sosllQWEy308XpiqmmrGaZg7XO06pffN%2B%2BIX2jqzMJvqTfLBXxt84jLNzwYf5%2FMl66jm7B1RA1CiGgxKnE97e09TY2PVrV08%2BIugWSXUSKnJcF2B8mL2uOxypeeBukg%2BROgcqWhseLNS1rQTugtcVivrKg%2FdruhK4tHLeSsH%2FFKmW2vm1egw%2By4quFhxDaN%2BN0kSs1zhNY%2BoRq6xy8zSOHRHrFQrrtUtZIfsr%2Fl09WRUbvqhxylhJ818vF%2BsQhzlgILmkoYvu2MGnQafwWZSNdMSyw9eEaohmXoxmhDo%2Butq3OVdZ%2Fo6ethXp8VUDrHqBXF4WiIXY8l2lnQh0sjdfgoVEjbDbp2B6X4bpL22vZ5AiXQGl0VusLji5Gs2w%2FVIjXsOBWszwp8Fah%2Bru%2FwMVMtTHcUSpVben%2Bk%2Bu14DNDSQSU%2FEI5QcTaFSRy6WOCqm0UyaWoNm96ReLscj6nNrQwSHbzH2ckpRC5cHXO%2FU%2BtDER7SeF%2F6CnCEdr6zlPLIRVSyirFq4fZOQ6aFM2izcMUye4aZ3Z93mk5PqCQJ%2F8qyiL5sGMz38egfQCW5Ogs2LDT9y3g4RHiKiTxr%2FWPxLniUB6DGktK7mNjwqy5hfQ2syE%2FGEy9IsETMLT2KemRfaqB1JiW8OG%2FKLRmI%2BFnLlNFulnquLIxI6VPvULnCDk7YoBqyyvKvgMyKdkUo7KpLjr3O%2BumDbKhgpETvpcO53VObs%2BABW%2Bse8NBXdYUSsQIy%2FFJaFW5Olw1Z4jzNRTE3fZiL1NuQDrEJnFygObw5nkz3uC%2Fq6jFU39Yrj0oUmiaCHbEnrFi736JZqPFYpDFLdQSMfLRcrX6d2a96AJ2x1DwStum3xm0eX2OwfEA5w2AH3aumQ%2Bw9xgLhrWo9uyRaOh3rKQzq5B%2FQygwtz3YmXRXb1adLVvLBm4t7Ofdjo%2BhE6t%2FU8hVDuU0Gd2lsC3gfMsHNtMwTL1skxMiv34wphB4vC4TVCx%2BxMS8eDRaczzRRJ3%2Fytc%2F3r4v%2B%2BIbx%2FvWf8eLOAf%2Bem%2B%2F5v&Signature=imoCHv%2B9tiVuA5izEjBxSh63f8cE8aBQkBtwljdEV2AMz%2FZs7NLRJgB%2BmEAnDvtEd2qgLYyn38bB0h4RXkxW5x4QpWqW4Kv%2BNpNQ5M4RpQKb8AGK7iHVvmFEt8FcELtlR7YxNkESnw9Eq6xHwGvX8QJhNNU6g6suvOOz1lhl0aSb2sej%2BZlFSl%2F%2FCP7c06EPpGwK%2FMVsCC5SL6iTeVCaOq%2BdVDKVsF9uzUg1iLDe7%2F3zU%2FfTLhSUutBH%2FJShWV6p%2BF3TSriN7g60FERh5VmaVZF1Ps31hjrR2IIb%2FanqtwmuP0DhpxC7%2BG1Ue9PyCy6RTMsuXHcBIOslNTt1rB%2FAGg%3D%3D&SigAlg=http%3A%2F%2Fwww.w3.org%2F2000%2F09%2Fxmldsig%23rsa-sha1 HTTP/1.1
292
  Connection: keep-alive
293
  User-Agent: Open eCard App/1.3.0
294
  Host: eid1.eid-service.de:443
295
  Accept: text/xml, */*;q=0.8
296
  Accept-Charset: utf-8, *;q=0.8
297

    
298
2018-12-20 21:02:23,973+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:267 - Sending HTTP request.
299
2018-12-20 21:02:24,490+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:270 - HTTP response received.
300
2018-12-20 21:02:24,493+01 [Thread-7] DEBUG o.o.transport.httpcore.HttpUtils:112 - HTTP Response:
301
  HTTP/1.1 302 Found
302
  Cache-Control: HTTP/1.1 302 Moved Temporarilyno-cache, no-store
303
  Server: HTTP/1.1 302 Moved Temporarilyno-cache, no-storeApache-Coyote/1.1
304
  Content-Security-Policy: HTTP/1.1 302 Moved Temporarilyno-cache, no-storeApache-Coyote/1.1default-src 'self'
305
  Pragma: HTTP/1.1 302 Moved Temporarilyno-cache, no-storeApache-Coyote/1.1default-src 'self'no-cache
306
  Content-Length: 0
307
  Date: HTTP/1.1 302 Moved Temporarilyno-cache, no-storeApache-Coyote/1.1default-src 'self'no-cache0Thu, 20 Dec 2018 20:02:24 GMT
308
  Location: https://eid1.eid-service.de:443/ecardpaos/startauthentication?DateOfBirth=true&IssuingState=true&DocumentType=true&FamilyNames=true&receiverUrl=https%3A%2F%2Feid2.eid-service.de%3A443%2Fecardpaos%2Fpaosreceiver&Nationality=true&PlaceOfBirth=true&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%23rsa-sha256&requestID=2fe8c06b-3f23-417c-8287-9bc48e5b554b&GivenNames=true&Signature=CZVyGJ1QS7TukyCUO%2F4Qbbhfgi%2Fm5DNuWCUWiICru%2FIyQO%2FhQaIodvEeqItWWKV5x1sjpNhOFUeNWzpiZshgbdMxzRsxoLOvhLoegvmTDFZyzvz4OYR5F0v9s5UyObssYwMibTjCRc73AVGv%2Bd0KUaZ64bwcJBjWeg%2FCnQ4bNsBN4iIxNzkSMEO0YVsttkhqanfVG2qMGH0qnrTc%2BVygaFo40nxkEIvT1vsvro%2FG5PRfii4VcW2oxzutppA%2FmuU6peLNZDyv%2B49Fn0FYDMkIRy9KFvNY4E4%2BSjTyL0xAxoTWMa7TwzYgwbV3DBukkzlN%2FV3eMSAN81k6lvrdl99Cxw%3D%3D&PlaceOfResidence=true&BirthName=true&idProviderUrl=https%3A%2F%2Feid1.eid-service.de%3A443%2Fgov_autent%2Fasync%3FrefID%3D_553c069918ad166b6beeb0490bb06e900f9be4b5
309

    
310

    
311
2018-12-20 21:02:24,493+01 [Thread-7] INFO  o.o.c.t.ClientCertDefaultTlsClient:298 - TLS warning sent.
312
2018-12-20 21:02:24,494+01 [Thread-7] INFO  o.o.c.t.ClientCertDefaultTlsClient:300 - TLS(WARN): Close [close_notify=0] --> Connection closed
313
2018-12-20 21:02:24,495+01 [Thread-7] INFO  o.o.binding.tctoken.ResourceContext:207 - Trying to load resource from: https://eid1.eid-service.de:443/ecardpaos/startauthentication?DateOfBirth=true&IssuingState=true&DocumentType=true&FamilyNames=true&receiverUrl=https%3A%2F%2Feid2.eid-service.de%3A443%2Fecardpaos%2Fpaosreceiver&Nationality=true&PlaceOfBirth=true&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%23rsa-sha256&requestID=2fe8c06b-3f23-417c-8287-9bc48e5b554b&GivenNames=true&Signature=CZVyGJ1QS7TukyCUO%2F4Qbbhfgi%2Fm5DNuWCUWiICru%2FIyQO%2FhQaIodvEeqItWWKV5x1sjpNhOFUeNWzpiZshgbdMxzRsxoLOvhLoegvmTDFZyzvz4OYR5F0v9s5UyObssYwMibTjCRc73AVGv%2Bd0KUaZ64bwcJBjWeg%2FCnQ4bNsBN4iIxNzkSMEO0YVsttkhqanfVG2qMGH0qnrTc%2BVygaFo40nxkEIvT1vsvro%2FG5PRfii4VcW2oxzutppA%2FmuU6peLNZDyv%2B49Fn0FYDMkIRy9KFvNY4E4%2BSjTyL0xAxoTWMa7TwzYgwbV3DBukkzlN%2FV3eMSAN81k6lvrdl99Cxw%3D%3D&PlaceOfResidence=true&BirthName=true&idProviderUrl=https%3A%2F%2Feid1.eid-service.de%3A443%2Fgov_autent%2Fasync%3FrefID%3D_553c069918ad166b6beeb0490bb06e900f9be4b5
314
2018-12-20 21:02:24,495+01 [Thread-7] DEBUG o.o.crypto.tls.proxy.ProxySettings:133 - Selecting proxy: DIRECT
315
2018-12-20 21:02:24,496+01 [Thread-7] DEBUG o.o.crypto.tls.proxy.ProxySettings:168 - Using proxy (DIRECT) to obtain socket.
316
2018-12-20 21:02:25,004+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:244 - Performing TLS handshake.
317
2018-12-20 21:02:25,578+01 [Thread-7] DEBUG o.o.c.tls.verify.HostnameVerifier:126 - Comparing connection hostname against certificate hostname: [eid1.eid-service.de] [eid1.eid-service.de]
318
2018-12-20 21:02:26,859+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:246 - TLS handshake performed.
319
2018-12-20 21:02:26,860+01 [Thread-7] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request:
320
  GET /ecardpaos/startauthentication?DateOfBirth=true&IssuingState=true&DocumentType=true&FamilyNames=true&receiverUrl=https%3A%2F%2Feid2.eid-service.de%3A443%2Fecardpaos%2Fpaosreceiver&Nationality=true&PlaceOfBirth=true&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%23rsa-sha256&requestID=2fe8c06b-3f23-417c-8287-9bc48e5b554b&GivenNames=true&Signature=CZVyGJ1QS7TukyCUO%2F4Qbbhfgi%2Fm5DNuWCUWiICru%2FIyQO%2FhQaIodvEeqItWWKV5x1sjpNhOFUeNWzpiZshgbdMxzRsxoLOvhLoegvmTDFZyzvz4OYR5F0v9s5UyObssYwMibTjCRc73AVGv%2Bd0KUaZ64bwcJBjWeg%2FCnQ4bNsBN4iIxNzkSMEO0YVsttkhqanfVG2qMGH0qnrTc%2BVygaFo40nxkEIvT1vsvro%2FG5PRfii4VcW2oxzutppA%2FmuU6peLNZDyv%2B49Fn0FYDMkIRy9KFvNY4E4%2BSjTyL0xAxoTWMa7TwzYgwbV3DBukkzlN%2FV3eMSAN81k6lvrdl99Cxw%3D%3D&PlaceOfResidence=true&BirthName=true&idProviderUrl=https%3A%2F%2Feid1.eid-service.de%3A443%2Fgov_autent%2Fasync%3FrefID%3D_553c069918ad166b6beeb0490bb06e900f9be4b5 HTTP/1.1
321
  Connection: keep-alive
322
  User-Agent: Open eCard App/1.3.0
323
  Host: eid1.eid-service.de:443
324
  Accept: text/xml, */*;q=0.8
325
  Accept-Charset: utf-8, *;q=0.8
326

    
327
2018-12-20 21:02:26,860+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:267 - Sending HTTP request.
328
2018-12-20 21:02:27,490+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:270 - HTTP response received.
329
2018-12-20 21:02:27,491+01 [Thread-7] DEBUG o.o.transport.httpcore.HttpUtils:112 - HTTP Response:
330
  HTTP/1.1 200 OK
331
  Server: HTTP/1.1 200 OKApache-Coyote/1.1
332
  Content-Security-Policy: HTTP/1.1 200 OKApache-Coyote/1.1default-src 'self'
333
  Content-Length: 652
334
  Date: HTTP/1.1 200 OKApache-Coyote/1.1default-src 'self'652Thu, 20 Dec 2018 20:02:27 GMT
335
  Content-Type: HTTP/1.1 200 OKApache-Coyote/1.1default-src 'self'652Thu, 20 Dec 2018 20:02:27 GMTtext/xml;charset=utf-8
336

    
337

    
338
2018-12-20 21:02:27,491+01 [Thread-7] DEBUG o.o.binding.tctoken.TCTokenContext:90 - Received TCToken:
339
<TCTokenType>
340
<ServerAddress>https://eid2.eid-service.de:443/ecardpaos/paosreceiver</ServerAddress>
341
<SessionIdentifier>2fe8c06b-3f23-417c-8287-9bc48e5b554b</SessionIdentifier>
342
<RefreshAddress>https://eid1.eid-service.de:443/gov_autent/async?refID=_553c069918ad166b6beeb0490bb06e900f9be4b5</RefreshAddress>
343
<CommunicationErrorAddress/>
344
<Binding>urn:liberty:paos:2006-08</Binding>
345
<PathSecurity-Protocol>urn:ietf:rfc:4279</PathSecurity-Protocol>
346
<PathSecurity-Parameters>
347
<PSK>95d5fb4e332b544f90d48452fa5101022aee8641b074d44420fdc0fac6dc9dbd621864634f2a1be31acd98990debfcf9a006811337b50cb621e5eb6bea8bbd63</PSK>
348
</PathSecurity-Parameters>
349
</TCTokenType>
350

    
351
2018-12-20 21:02:27,493+01 [Thread-7] DEBUG o.o.binding.tctoken.TCTokenContext:92 - Cleaned up TCToken:
352
<TCTokenType>
353
<ServerAddress>https://eid2.eid-service.de:443/ecardpaos/paosreceiver</ServerAddress>
354
<SessionIdentifier>2fe8c06b-3f23-417c-8287-9bc48e5b554b</SessionIdentifier>
355
<RefreshAddress>https://eid1.eid-service.de:443/gov_autent/async?refID=_553c069918ad166b6beeb0490bb06e900f9be4b5</RefreshAddress>
356
<CommunicationErrorAddress/>
357
<Binding>urn:liberty:paos:2006-08</Binding>
358
<PathSecurity-Protocol>urn:ietf:rfc:4279</PathSecurity-Protocol>
359
<PathSecurity-Parameters>
360
<PSK>95d5fb4e332b544f90d48452fa5101022aee8641b074d44420fdc0fac6dc9dbd621864634f2a1be31acd98990debfcf9a006811337b50cb621e5eb6bea8bbd63</PSK>
361
</PathSecurity-Parameters>
362
</TCTokenType>
363

    
364
2018-12-20 21:02:27,568+01 [Thread-7] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
365
2018-12-20 21:02:27,569+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
366
2018-12-20 21:02:27,569+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
367
2018-12-20 21:02:27,569+01 [Thread-7] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.CardApplicationPath
368
2018-12-20 21:02:27,589+01 [Thread-7] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
369
2018-12-20 21:02:27,589+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
370
2018-12-20 21:02:27,589+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
371
2018-12-20 21:02:27,594+01 [Thread-7] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
372
2018-12-20 21:02:27,594+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
373
2018-12-20 21:02:27,595+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
374
2018-12-20 21:02:27,596+01 [Thread-7] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.CardApplicationConnect
375
2018-12-20 21:02:27,598+01 [Thread-7] DEBUG o.o.common.util.HandlerUtils:132 - Found ContextHandle in object of type Connect.
376
2018-12-20 21:02:27,602+01 [Thread-7] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
377
2018-12-20 21:02:27,602+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
378
2018-12-20 21:02:27,602+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
379
2018-12-20 21:02:27,602+01 [Thread-7] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Connect
380
2018-12-20 21:02:27,602+01 [Thread-7] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'REINER SCT cyberJack RFID komfort (9394279424) 00 00' is already connected.
381
2018-12-20 21:02:27,618+01 [Thread-7] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
382
2018-12-20 21:02:27,618+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
383
2018-12-20 21:02:27,618+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
384
2018-12-20 21:02:27,623+01 [Thread-7] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
385
2018-12-20 21:02:27,628+01 [Thread-7] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
386
2018-12-20 21:02:27,629+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
387
2018-12-20 21:02:27,629+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
388
2018-12-20 21:02:27,629+01 [Thread-7] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
389
2018-12-20 21:02:27,630+01 [Thread-7] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 00A4000C023F00
390
2018-12-20 21:02:27,636+01 [Thread-7] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
391
2018-12-20 21:02:27,645+01 [Thread-7] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
392
2018-12-20 21:02:27,645+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
393
2018-12-20 21:02:27,645+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
394
2018-12-20 21:02:27,646+01 [Thread-7] DEBUG o.o.common.sal.state.CardStateMap:94 - Add new entry to card states: CardStateEntry@1 {
395
  handle=  ConnectionHandle {
396
    ctx=72E59137FF7BAF326A55F2DC1982D331
397
    ifd=REINER SCT cyberJack RFID komfort (9394279424) 00 00
398
    idx=0
399
    slot=2C332AAF2B51C1B4661D4E738A4F837E52EE9B9831220257
400
    app=3F00
401
    Recognition {
402
      typ=http://bsi.bund.de/cif/npa.xml
403
      ident=null
404
    }
405
  }
406
}
407
2018-12-20 21:02:27,653+01 [Thread-7] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
408
2018-12-20 21:02:27,655+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
409
2018-12-20 21:02:27,655+01 [Thread-7] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
410
2018-12-20 21:02:27,659+01 [PAOS] INFO  o.o.c.t.ClientCertDefaultTlsClient:298 - TLS warning sent.
411
2018-12-20 21:02:27,659+01 [PAOS] INFO  o.o.c.t.ClientCertDefaultTlsClient:300 - TLS(WARN): Close [close_notify=0] --> Connection closed
412
2018-12-20 21:02:27,687+01 [PAOS] DEBUG org.openecard.transport.paos.PAOS:470 - Opening connection to PAOS server.
413
2018-12-20 21:02:27,689+01 [PAOS] DEBUG o.o.crypto.tls.proxy.ProxySettings:133 - Selecting proxy: DIRECT
414
2018-12-20 21:02:27,689+01 [PAOS] DEBUG o.o.crypto.tls.proxy.ProxySettings:168 - Using proxy (DIRECT) to obtain socket.
415
2018-12-20 21:02:29,865+01 [PAOS] DEBUG o.o.c.tls.verify.HostnameVerifier:126 - Comparing connection hostname against certificate hostname: [eid2.eid-service.de] [eid2.eid-service.de]
416
2018-12-20 21:02:31,058+01 [PAOS] DEBUG org.openecard.transport.paos.PAOS:473 - Connection to PAOS server established.
417
2018-12-20 21:02:31,064+01 [PAOS] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request (before adding content):
418
  POST /ecardpaos/paosreceiver HTTP/1.1
419
  Connection: keep-alive
420
  User-Agent: Open eCard App/1.3.0
421
  Host: eid2.eid-service.de:443
422
  PAOS: ver="urn:liberty:paos:2006-08" ;"urn:iso:std:iso-iec:24727:tech:schema:Transmit";"http://www.bsi.bund.de/ecard/api/1.0#InitializeFramework";"urn:iso:std:iso-iec:24727:tech:schema:StartSession";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationEndSession";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationList";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationServiceList";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationServiceDescribe";"urn:iso:std:iso-iec:24727:tech:schema:DataSetList";"urn:iso:std:iso-iec:24727:tech:schema:DataSetSelect";"urn:iso:std:iso-iec:24727:tech:schema:DSIList";"urn:iso:std:iso-iec:24727:tech:schema:DSIWrite";"urn:iso:std:iso-iec:24727:tech:schema:DSIRead";"urn:iso:std:iso-iec:24727:tech:schema:Encipher";"urn:iso:std:iso-iec:24727:tech:schema:Decipher";"urn:iso:std:iso-iec:24727:tech:schema:GetRandom";"urn:iso:std:iso-iec:24727:tech:schema:Sign";"urn:iso:std:iso-iec:24727:tech:schema:VerifySignature";"urn:iso:std:iso-iec:24727:tech:schema:VerifyCertificate";"urn:iso:std:iso-iec:24727:tech:schema:DIDList";"urn:iso:std:iso-iec:24727:tech:schema:DIDGet";"urn:iso:std:iso-iec:24727:tech:schema:DIDAuthenticate";"urn:iso:std:iso-iec:24727:tech:schema:ACLList";"urn:iso:std:iso-iec:24727:tech:schema:Hash"
423
  Accept: text/xml, application/xml, application/vnd.paos+xml
424

    
425
2018-12-20 21:02:31,151+01 [PAOS] DEBUG org.openecard.transport.paos.PAOS:268 - Message sent:
426
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
427
<Envelope xmlns="http://schemas.xmlsoap.org/soap/envelope/">
428
  <Header>
429
    <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">
430
      <Version>urn:liberty:paos:2006-08</Version>
431
      <EndpointReference>
432
        <Address>http://www.projectliberty.org/2006/01/role/paos</Address>
433
        <MetaData>
434
          <ServiceType>http://www.bsi.bund.de/ecard/api/1.1/PAOS/GetNextCommand</ServiceType>
435
        </MetaData>
436
      </EndpointReference>
437
    </PAOS>
438
    <ReplyTo xmlns="http://www.w3.org/2005/03/addressing">
439
      <Address>http://www.projectliberty.org/2006/02/role/paos</Address>
440
    </ReplyTo>
441
    <MessageID xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:f0c508a7-227e-4760-966d-7cbe93bda4c9</MessageID>
442
  </Header>
443
  <Body>
444
    <ns3:StartPAOS xmlns="urn:oasis:names:tc:dss:1.0:core:schema" 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="http://www.bsi.bund.de/ecard/api/1.1" 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="http://uri.etsi.org/01903/v1.3.2#" xmlns:ns9="urn:oasis:names:tc:dss-x:1.0:profiles:verificationreport:schema#" Profile="http://www.bsi.bund.de/ecard/api/1.1">
445
      <ns3:SessionIdentifier>2fe8c06b-3f23-417c-8287-9bc48e5b554b</ns3:SessionIdentifier>
446
      <ns3:ConnectionHandle>
447
        <ns3:ChannelHandle>
448
          <ns3:SessionIdentifier>EjRS8YywdxcQWtM990olOw</ns3:SessionIdentifier>
449
        </ns3:ChannelHandle>
450
        <ns3:ContextHandle>72E59137FF7BAF326A55F2DC1982D331</ns3:ContextHandle>
451
        <ns3:IFDName>REINER SCT cyberJack RFID komfort (9394279424) 00 00</ns3:IFDName>
452
        <ns3:SlotIndex>0</ns3:SlotIndex>
453
        <ns3:CardApplication>3F00</ns3:CardApplication>
454
        <ns3:SlotHandle>2C332AAF2B51C1B4661D4E738A4F837E52EE9B9831220257</ns3:SlotHandle>
455
        <ns3:RecognitionInfo>
456
          <ns3:CardType>http://bsi.bund.de/cif/npa.xml</ns3:CardType>
457
        </ns3:RecognitionInfo>
458
      </ns3:ConnectionHandle>
459
      <ns3:UserAgent>
460
        <ns3:Name>Open eCard App</ns3:Name>
461
        <ns3:VersionMajor>1</ns3:VersionMajor>
462
        <ns3:VersionMinor>3</ns3:VersionMinor>
463
        <ns3:VersionSubminor>0</ns3:VersionSubminor>
464
      </ns3:UserAgent>
465
      <ns3:SupportedAPIVersions>
466
        <ns3:Major>1</ns3:Major>
467
        <ns3:Minor>1</ns3:Minor>
468
        <ns3:Subminor>5</ns3:Subminor>
469
      </ns3:SupportedAPIVersions>
470
      <ns3:SupportedDIDProtocols>urn:oid:1.3.162.15480.3.0.14</ns3:SupportedDIDProtocols>
471
      <ns3:SupportedDIDProtocols>urn:oid:1.3.162.15480.3.0.14.2</ns3:SupportedDIDProtocols>
472
      <ns3:SupportedDIDProtocols>urn:oid:1.3.162.15480.3.0.25</ns3:SupportedDIDProtocols>
473
      <ns3:SupportedDIDProtocols>urn:oid:1.3.162.15480.3.0.9</ns3:SupportedDIDProtocols>
474
    </ns3:StartPAOS>
475
  </Body>
476
</Envelope>
477

    
478
2018-12-20 21:02:31,152+01 [PAOS] DEBUG org.openecard.transport.paos.PAOS:363 - Sending HTTP request.
479
2018-12-20 21:02:32,961+01 [PAOS] DEBUG org.openecard.transport.paos.PAOS:365 - HTTP response received.
480
2018-12-20 21:02:32,962+01 [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)
481
2018-12-20 21:02:32,963+01 [PAOS] DEBUG o.o.transport.httpcore.HttpUtils:112 - HTTP Response:
482
  HTTP/1.1 200 OK
483
  Server: HTTP/1.1 200 OKApache-Coyote/1.1
484
  Content-Security-Policy: HTTP/1.1 200 OKApache-Coyote/1.1default-src 'self'
485
  Content-Length: HTTP/1.1 200 OKApache-Coyote/1.1default-src 'self'8208
486
  Date: HTTP/1.1 200 OKApache-Coyote/1.1default-src 'self'8208Thu, 20 Dec 2018 20:02:32 GMT
487
  Content-Type: HTTP/1.1 200 OKApache-Coyote/1.1default-src 'self'8208Thu, 20 Dec 2018 20:02:32 GMTapplication/vnd.paos+xml
488
  Transfer-Encoding: chunked
489
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
490
<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/">
491
   <soap:Header>
492
      <sb:Correlation xmlns:sb="http://urn:liberty:sb:2003-08" messageID="Id124698" refToMessageID="2fe8c06b-3f23-417c-8287-9bc48e5b554b"/>
493
      <RelatesTo xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:f0c508a7-227e-4760-966d-7cbe93bda4c9</RelatesTo>
494
      <MessageID xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:c4c68538-8b34-427e-9d18-03d4bd86afe4</MessageID>
495
   </soap:Header>
496
   <soap:Body>
497
   <ns2:DIDAuthenticate xmlns:ns2="urn:iso:std:iso-iec:24727:tech:schema" xmlns:ns3="urn:oasis:names:tc:dss:1.0:core:schema" xmlns:ns4="http://www.w3.org/2000/09/xmldsig#">
498
      <ns2:ConnectionHandle>
499
        <ns2:ChannelHandle>
500
          <ns2:SessionIdentifier>EjRS8YywdxcQWtM990olOw</ns2:SessionIdentifier>
501
        </ns2:ChannelHandle>
502
        <ns2:ContextHandle>72E59137FF7BAF326A55F2DC1982D331</ns2:ContextHandle>
503
        <ns2:IFDName>REINER SCT cyberJack RFID komfort (9394279424) 00 00</ns2:IFDName>
504
        <ns2:SlotIndex>0</ns2:SlotIndex>
505
        <ns2:CardApplication>3F00</ns2:CardApplication>
506
        <ns2:SlotHandle>2C332AAF2B51C1B4661D4E738A4F837E52EE9B9831220257</ns2:SlotHandle>
507
        <ns2:RecognitionInfo>
508
          <ns2:CardType>http://bsi.bund.de/cif/npa.xml</ns2:CardType>
509
        </ns2:RecognitionInfo>
510
      </ns2:ConnectionHandle>
511
      <ns2:DIDName>PIN</ns2:DIDName>
512
      <ns2:AuthenticationProtocolData xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" Protocol="urn:oid:1.3.162.15480.3.0.14.2" xsi:type="ns2:EAC1InputType">
513
        <ns2:Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201487f4e8201005f2901004210444544566549444454523130313433367f494f060a04007f0007020202020386410405559d8f83507952b54b0baf1dfff3afd6be50cb0f5f9c9c398b1f39171d9c3398c14bb3b8cc8cce92c091c924ba329dff8d8becc93cc3454b3b1c11edd120465f200e44453030303032313830323430327f4c12060904007f00070301020253050001139b005f25060108010202005f2406010801020201655e732d060904007f0007030103028020497ea2b8b286fc3f57624f9bc452d1e1453f4814c243c2b22b3bd217324b55e7732d060904007f00070301030180207086676358f9682c3cc56f6e6f0452eee92d20459c4f4508fdfa3a48a4854f5c5f374048864858f335279b360f3145ee0186247364f75673d94ebe5e6a65e31e58113a786920f990ff47ac61ef899d4462dea34d7d52a56e5c3c029595dc57c6656f4a</ns2:Certificate>
514
        <ns2:Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201b67f4e82016e5f290100420e44454356434165494430303130327f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a78641048925419fc7f194922cfc6b8dd25ae6a19c1b59216e6cf06270e5d75cfd64205f55cf867bbfefeefd6e680e1fd197f18ab684484901362568efc9adb5c6018d728701015f200e44454356434165494430303130337f4c12060904007f0007030102025305fc0f13ffff5f25060102010200035f24060105010200035f37404d6f08a86a4f18409f6685387dd3c6a7ff5d68ea4f7714a861bbb3bb721d05d3014adf1763c9292f715d8e94ee9b3e1b73ab1382414ebf39dfb3b0fb6c09dbeb</ns2:Certificate>
515
        <ns2:Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201b67f4e82016e5f290100420e44454356434165494430303130337f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a7864104241d8627338b64f20077ffd558909a096c635ddb222852038eaae642e869a40173d588f817d95db2a6a0f077ea5ee63596a20f85bc3cb176d2f98d88d90219aa8701015f200e44454356434165494430303130347f4c12060904007f0007030102025305fc0f13ffff5f25060105000901045f24060108000901045f3740313a81ed8734e7a8c45f16b55fb603e63027b7f44c2de3a8e782552d35949db221ca33bd41a01da6a1288c7885714fc3a03fa45683b75d3884930ec6738af8a0</ns2:Certificate>
516
        <ns2:Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201b67f4e82016e5f290100420e44454356434165494430303130347f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a786410459d1a08a2572022e17fed831982a9cb904518003cf83dabed88dbed28963768b88dba22a153558bd21ddaa99318378b7cd7ebfe849557cd43f8526abe72734538701015f200e44454356434165494430303130357f4c12060904007f0007030102025305fc0f13ffff5f25060108000601025f24060201000601025f37402fbeeae1b1ade6cfb6cab9d9b19f6a6efacb7d9701997f43cf608bf72cf496f485f691e75190dec25c672b92cf9ba917883659a6dc16793d22bbec4019c616cc</ns2:Certificate>
517
        <ns2:Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f2181e77f4e81a05f290100420e44454356434165494430303130357f494f060a04007f000702020202038641040c8d7b4e5fac5d0a0dd12d50a652d1d6c3b01d777c45e154c22f4a7f8be784d56f64204297ab4343ca88e95dc2b0046f6db1b46c15149b74631b6ff3f0911e975f2010444544566549444454523130313433367f4c12060904007f0007030102025305400513ff975f25060108010201035f24060109000301035f37409b7cd45eb63d3280517e92323fdc2e8258814b3c82a7418588a9698f0d95558a84b0407b8a3b50cbf31c24751b7f1568a3bcc664443b754016f6d20350b1eaa3</ns2:Certificate>
518
        <ns2:CertificateDescription xmlns="urn:iso:std:iso-iec:24727:tech:schema">30820329060a04007f00070301030101a10e0c0c442d547275737420476d6248a2181316687474703a2f2f7777772e642d74727573742e6e6574a3170c1542756e646573616d742066c3bc72204a757374697aa42a132868747470733a2f2f7777772e6675656872756e67737a6575676e69732e62756e642e64652f666677a58201d80c8201d44e616d652c20416e7363687269667420756e6420452d4d61696c2d4164726573736520646573204469656e737465616e626965746572733a0d0a42756e646573616d742066c3bc72204a757374697a0d0a4164656e61756572616c6c65652039392d3130330d0a353331313320426f6e6e0d0a72656769737465726175736b756e66742d6f6e6c696e654062666a2e62756e642e64650d0a0d0a4765736368c3a46674737a7765636b3a0d0a4f6e6c696e652d416e74726167206175662045727465696c756e6720766f6e2046c3bc6872756e67737a6575676e697373656e20756e6420476577657262657a656e7472616c72656769737465726175736bc3bc6e6674656e0d0a0d0a5a757374c3a46e6469676520446174656e73636875747a626568c3b67264653a0d0a4469652042756e64657362656175667472616774652066c3bc722064656e20446174656e73636875747a20756e642064696520496e666f726d6174696f6e7366726569686569740d0a4875736172656e73747261c39f652033300d0a353331313720426f6e6e0d0a303232382d3939373739392d300d0a706f73747374656c6c6540626664692e62756e642e64650d0a687474703a2f2f7777772e626664692e62756e642e64650d0aa781cf3181cc042008198a75e92bcc93cdff9383603d686b153b1c589ed3e0096a408f5e2e711c6c042047d84367639ac114b7ce5bfce6b7aa30cea10a9d33101cc383268047f082417c042087942ed74e7bd9d8ec866d8d76cb4b8d71b5b6b4863b7d48a1586a8603b9627f04209b9d1df98b9ee3b2c90e62dc501c5c68b5c97f1154316d55f420f57a6d345dbb0420c9910fa727feebc2a638810e5258a32c53e270b12d42c44c98a64e574b0e95da0420f851e83b3b81d3e11f27e3b97be79cfbdb344176493f70bdcb0a5cba8c9089a8</ns2:CertificateDescription>
519
        <ns2:RequiredCHAT xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f4c12060904007f00070301020253050001139b00</ns2:RequiredCHAT>
520
        <ns2:OptionalCHAT xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f4c12060904007f00070301020253050000000000</ns2:OptionalCHAT>
521
        <ns2:AuthenticatedAuxiliaryData xmlns="urn:iso:std:iso-iec:24727:tech:schema">67177315060904007f00070301040253083230313831323230</ns2:AuthenticatedAuxiliaryData>
522
        <ns2:TransactionInfo xmlns="urn:iso:std:iso-iec:24727:tech:schema"/>
523
      </ns2:AuthenticationProtocolData>
524
    </ns2:DIDAuthenticate>
525
  </soap:Body>
526
</soap:Envelope>
527

    
528

    
529
2018-12-20 21:02:32,976+01 [PAOS] DEBUG org.openecard.transport.paos.PAOS:224 - Message received:
530
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
531
<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/">
532
  <soap:Header>
533
    <sb:Correlation xmlns:sb="http://urn:liberty:sb:2003-08" messageID="Id124698" refToMessageID="2fe8c06b-3f23-417c-8287-9bc48e5b554b"/>
534
    <RelatesTo xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:f0c508a7-227e-4760-966d-7cbe93bda4c9</RelatesTo>
535
    <MessageID xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:c4c68538-8b34-427e-9d18-03d4bd86afe4</MessageID>
536
  </soap:Header>
537
  <soap:Body>
538
    <ns2:DIDAuthenticate xmlns:ns2="urn:iso:std:iso-iec:24727:tech:schema" xmlns:ns3="urn:oasis:names:tc:dss:1.0:core:schema" xmlns:ns4="http://www.w3.org/2000/09/xmldsig#">
539
      <ns2:ConnectionHandle>
540
        <ns2:ChannelHandle>
541
          <ns2:SessionIdentifier>EjRS8YywdxcQWtM990olOw</ns2:SessionIdentifier>
542
        </ns2:ChannelHandle>
543
        <ns2:ContextHandle>72E59137FF7BAF326A55F2DC1982D331</ns2:ContextHandle>
544
        <ns2:IFDName>REINER SCT cyberJack RFID komfort (9394279424) 00 00</ns2:IFDName>
545
        <ns2:SlotIndex>0</ns2:SlotIndex>
546
        <ns2:CardApplication>3F00</ns2:CardApplication>
547
        <ns2:SlotHandle>2C332AAF2B51C1B4661D4E738A4F837E52EE9B9831220257</ns2:SlotHandle>
548
        <ns2:RecognitionInfo>
549
          <ns2:CardType>http://bsi.bund.de/cif/npa.xml</ns2:CardType>
550
        </ns2:RecognitionInfo>
551
      </ns2:ConnectionHandle>
552
      <ns2:DIDName>PIN</ns2:DIDName>
553
      <ns2:AuthenticationProtocolData xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" Protocol="urn:oid:1.3.162.15480.3.0.14.2" xsi:type="ns2:EAC1InputType">
554
        <ns2:Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201487f4e8201005f2901004210444544566549444454523130313433367f494f060a04007f0007020202020386410405559d8f83507952b54b0baf1dfff3afd6be50cb0f5f9c9c398b1f39171d9c3398c14bb3b8cc8cce92c091c924ba329dff8d8becc93cc3454b3b1c11edd120465f200e44453030303032313830323430327f4c12060904007f00070301020253050001139b005f25060108010202005f2406010801020201655e732d060904007f0007030103028020497ea2b8b286fc3f57624f9bc452d1e1453f4814c243c2b22b3bd217324b55e7732d060904007f00070301030180207086676358f9682c3cc56f6e6f0452eee92d20459c4f4508fdfa3a48a4854f5c5f374048864858f335279b360f3145ee0186247364f75673d94ebe5e6a65e31e58113a786920f990ff47ac61ef899d4462dea34d7d52a56e5c3c029595dc57c6656f4a</ns2:Certificate>
555
        <ns2:Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201b67f4e82016e5f290100420e44454356434165494430303130327f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a78641048925419fc7f194922cfc6b8dd25ae6a19c1b59216e6cf06270e5d75cfd64205f55cf867bbfefeefd6e680e1fd197f18ab684484901362568efc9adb5c6018d728701015f200e44454356434165494430303130337f4c12060904007f0007030102025305fc0f13ffff5f25060102010200035f24060105010200035f37404d6f08a86a4f18409f6685387dd3c6a7ff5d68ea4f7714a861bbb3bb721d05d3014adf1763c9292f715d8e94ee9b3e1b73ab1382414ebf39dfb3b0fb6c09dbeb</ns2:Certificate>
556
        <ns2:Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201b67f4e82016e5f290100420e44454356434165494430303130337f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a7864104241d8627338b64f20077ffd558909a096c635ddb222852038eaae642e869a40173d588f817d95db2a6a0f077ea5ee63596a20f85bc3cb176d2f98d88d90219aa8701015f200e44454356434165494430303130347f4c12060904007f0007030102025305fc0f13ffff5f25060105000901045f24060108000901045f3740313a81ed8734e7a8c45f16b55fb603e63027b7f44c2de3a8e782552d35949db221ca33bd41a01da6a1288c7885714fc3a03fa45683b75d3884930ec6738af8a0</ns2:Certificate>
557
        <ns2:Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f218201b67f4e82016e5f290100420e44454356434165494430303130347f4982011d060a04007f000702020202038120a9fb57dba1eea9bc3e660a909d838d726e3bf623d52620282013481d1f6e537782207d5a0975fc2c3057eef67530417affe7fb8055c126dc5c6ce94a4b44f330b5d9832026dc5c6ce94a4b44f330b5d9bbd77cbf958416295cf7e1ce6bccdc18ff8c07b68441048bd2aeb9cb7e57cb2c4b482ffc81b7afb9de27e1e3bd23c23a4453bd9ace3262547ef835c3dac4fd97f8461a14611dc9c27745132ded8e545c1d54c72f0469978520a9fb57dba1eea9bc3e660a909d838d718c397aa3b561a6f7901e0e82974856a786410459d1a08a2572022e17fed831982a9cb904518003cf83dabed88dbed28963768b88dba22a153558bd21ddaa99318378b7cd7ebfe849557cd43f8526abe72734538701015f200e44454356434165494430303130357f4c12060904007f0007030102025305fc0f13ffff5f25060108000601025f24060201000601025f37402fbeeae1b1ade6cfb6cab9d9b19f6a6efacb7d9701997f43cf608bf72cf496f485f691e75190dec25c672b92cf9ba917883659a6dc16793d22bbec4019c616cc</ns2:Certificate>
558
        <ns2:Certificate xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f2181e77f4e81a05f290100420e44454356434165494430303130357f494f060a04007f000702020202038641040c8d7b4e5fac5d0a0dd12d50a652d1d6c3b01d777c45e154c22f4a7f8be784d56f64204297ab4343ca88e95dc2b0046f6db1b46c15149b74631b6ff3f0911e975f2010444544566549444454523130313433367f4c12060904007f0007030102025305400513ff975f25060108010201035f24060109000301035f37409b7cd45eb63d3280517e92323fdc2e8258814b3c82a7418588a9698f0d95558a84b0407b8a3b50cbf31c24751b7f1568a3bcc664443b754016f6d20350b1eaa3</ns2:Certificate>
559
        <ns2:CertificateDescription xmlns="urn:iso:std:iso-iec:24727:tech:schema">30820329060a04007f00070301030101a10e0c0c442d547275737420476d6248a2181316687474703a2f2f7777772e642d74727573742e6e6574a3170c1542756e646573616d742066c3bc72204a757374697aa42a132868747470733a2f2f7777772e6675656872756e67737a6575676e69732e62756e642e64652f666677a58201d80c8201d44e616d652c20416e7363687269667420756e6420452d4d61696c2d4164726573736520646573204469656e737465616e626965746572733a0d0a42756e646573616d742066c3bc72204a757374697a0d0a4164656e61756572616c6c65652039392d3130330d0a353331313320426f6e6e0d0a72656769737465726175736b756e66742d6f6e6c696e654062666a2e62756e642e64650d0a0d0a4765736368c3a46674737a7765636b3a0d0a4f6e6c696e652d416e74726167206175662045727465696c756e6720766f6e2046c3bc6872756e67737a6575676e697373656e20756e6420476577657262657a656e7472616c72656769737465726175736bc3bc6e6674656e0d0a0d0a5a757374c3a46e6469676520446174656e73636875747a626568c3b67264653a0d0a4469652042756e64657362656175667472616774652066c3bc722064656e20446174656e73636875747a20756e642064696520496e666f726d6174696f6e7366726569686569740d0a4875736172656e73747261c39f652033300d0a353331313720426f6e6e0d0a303232382d3939373739392d300d0a706f73747374656c6c6540626664692e62756e642e64650d0a687474703a2f2f7777772e626664692e62756e642e64650d0aa781cf3181cc042008198a75e92bcc93cdff9383603d686b153b1c589ed3e0096a408f5e2e711c6c042047d84367639ac114b7ce5bfce6b7aa30cea10a9d33101cc383268047f082417c042087942ed74e7bd9d8ec866d8d76cb4b8d71b5b6b4863b7d48a1586a8603b9627f04209b9d1df98b9ee3b2c90e62dc501c5c68b5c97f1154316d55f420f57a6d345dbb0420c9910fa727feebc2a638810e5258a32c53e270b12d42c44c98a64e574b0e95da0420f851e83b3b81d3e11f27e3b97be79cfbdb344176493f70bdcb0a5cba8c9089a8</ns2:CertificateDescription>
560
        <ns2:RequiredCHAT xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f4c12060904007f00070301020253050001139b00</ns2:RequiredCHAT>
561
        <ns2:OptionalCHAT xmlns="urn:iso:std:iso-iec:24727:tech:schema">7f4c12060904007f00070301020253050000000000</ns2:OptionalCHAT>
562
        <ns2:AuthenticatedAuxiliaryData xmlns="urn:iso:std:iso-iec:24727:tech:schema">67177315060904007f00070301040253083230313831323230</ns2:AuthenticatedAuxiliaryData>
563
        <ns2:TransactionInfo xmlns="urn:iso:std:iso-iec:24727:tech:schema"/>
564
      </ns2:AuthenticationProtocolData>
565
    </ns2:DIDAuthenticate>
566
  </soap:Body>
567
</soap:Envelope>
568

    
569
2018-12-20 21:02:32,995+01 [PAOS] DEBUG o.o.common.util.HandlerUtils:125 - Found ConnectionHandle in object of type DIDAuthenticate.
570
2018-12-20 21:02:33,041+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
571
2018-12-20 21:02:33,042+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
572
2018-12-20 21:02:33,042+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
573
2018-12-20 21:02:33,042+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.DIDAuthenticate
574
2018-12-20 21:02:33,050+01 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:71 - Requesting entry (filterAppId=true) for handle:
575
ConnectionHandle:
576
  Session: EjRS8YywdxcQWtM990olOw
577
  ContextHandle: 72E59137FF7BAF326A55F2DC1982D331
578
  IFDName: REINER SCT cyberJack RFID komfort (9394279424) 00 00  SlotIndex: 0
579
  SlotHandle: 2C332AAF2B51C1B4661D4E738A4F837E52EE9B9831220257
580
  CardType: http://bsi.bund.de/cif/npa.xml
581
2018-12-20 21:02:33,051+01 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:73 - Current state entries are:
582
2018-12-20 21:02:33,051+01 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:75 - CardStateEntry@0 {
583
  handle=  ConnectionHandle {
584
    ctx=72E59137FF7BAF326A55F2DC1982D331
585
    ifd=REINER SCT cyberJack RFID komfort (9394279424) 00 00
586
    idx=0
587
    slot=null
588
    app=3F00
589
    Recognition {
590
      typ=http://bsi.bund.de/cif/npa.xml
591
      ident=null
592
    }
593
  }
594
}
595

    
596
2018-12-20 21:02:33,052+01 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:75 - CardStateEntry@1 {
597
  handle=  ConnectionHandle {
598
    ctx=72E59137FF7BAF326A55F2DC1982D331
599
    ifd=REINER SCT cyberJack RFID komfort (9394279424) 00 00
600
    idx=0
601
    slot=2C332AAF2B51C1B4661D4E738A4F837E52EE9B9831220257
602
    app=3F00
603
    Recognition {
604
      typ=http://bsi.bund.de/cif/npa.xml
605
      ident=null
606
    }
607
  }
608
}
609

    
610
2018-12-20 21:02:33,115+01 [PAOS] WARN  org.openecard.common.I18n:152 - Failed to load resource eac for lang de_DE.
611
2018-12-20 21:02:33,168+01 [PAOS] DEBUG o.o.common.util.HandlerUtils:132 - Found ContextHandle in object of type GetIFDCapabilities.
612
2018-12-20 21:02:33,173+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
613
2018-12-20 21:02:33,174+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
614
2018-12-20 21:02:33,174+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
615
2018-12-20 21:02:33,175+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.GetIFDCapabilities
616
2018-12-20 21:02:33,175+01 [PAOS] WARN  o.o.ifd.scio.wrapper.ChannelManager:87 - Terminal 'REINER SCT cyberJack RFID komfort (9394279424) 00 00' is already connected.
617
2018-12-20 21:02:33,186+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
618
2018-12-20 21:02:33,187+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
619
2018-12-20 21:02:33,187+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
620
2018-12-20 21:02:33,190+01 [PAOS] WARN  o.o.c.c.a.c.CardVerifiableCertificateChain:60 - Verification of the certificate chain is disabled.
621
2018-12-20 21:02:33,193+01 [PAOS] INFO  o.o.common.util.TR03112Utils:107 - Checking certificate hash of eService against list of communication certificates.
622
2018-12-20 21:02:33,195+01 [PAOS] DEBUG o.o.common.util.TR03112Utils:115 - Hash of the retrieved server certificate: 87942ED74E7BD9D8EC866D8D76CB4B8D71B5B6B4863B7D48A1586A8603B9627F
623
2018-12-20 21:02:33,195+01 [PAOS] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 08198A75E92BCC93CDFF9383603D686B153B1C589ED3E0096A408F5E2E711C6C
624
2018-12-20 21:02:33,196+01 [PAOS] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 47D84367639AC114B7CE5BFCE6B7AA30CEA10A9D33101CC383268047F082417C
625
2018-12-20 21:02:33,197+01 [PAOS] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 87942ED74E7BD9D8EC866D8D76CB4B8D71B5B6B4863B7D48A1586A8603B9627F
626
2018-12-20 21:02:33,197+01 [PAOS] INFO  o.o.common.util.TR03112Utils:107 - Checking certificate hash of https://www.fuehrungszeugnis.bund.de against list of communication certificates.
627
2018-12-20 21:02:33,200+01 [PAOS] DEBUG o.o.common.util.TR03112Utils:115 - Hash of the retrieved server certificate: 9B9D1DF98B9EE3B2C90E62DC501C5C68B5C97F1154316D55F420F57A6D345DBB
628
2018-12-20 21:02:33,201+01 [PAOS] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 08198A75E92BCC93CDFF9383603D686B153B1C589ED3E0096A408F5E2E711C6C
629
2018-12-20 21:02:33,201+01 [PAOS] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 47D84367639AC114B7CE5BFCE6B7AA30CEA10A9D33101CC383268047F082417C
630
2018-12-20 21:02:33,202+01 [PAOS] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 87942ED74E7BD9D8EC866D8D76CB4B8D71B5B6B4863B7D48A1586A8603B9627F
631
2018-12-20 21:02:33,202+01 [PAOS] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 9B9D1DF98B9EE3B2C90E62DC501C5C68B5C97F1154316D55F420F57A6D345DBB
632
2018-12-20 21:02:33,203+01 [PAOS] INFO  o.o.common.util.TR03112Utils:107 - Checking certificate hash of https://eid1.eid-service.de:443 against list of communication certificates.
633
2018-12-20 21:02:33,204+01 [PAOS] DEBUG o.o.common.util.TR03112Utils:115 - Hash of the retrieved server certificate: 08198A75E92BCC93CDFF9383603D686B153B1C589ED3E0096A408F5E2E711C6C
634
2018-12-20 21:02:33,205+01 [PAOS] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 08198A75E92BCC93CDFF9383603D686B153B1C589ED3E0096A408F5E2E711C6C
635
2018-12-20 21:02:33,205+01 [PAOS] INFO  o.o.common.util.TR03112Utils:107 - Checking certificate hash of https://eid1.eid-service.de:443 against list of communication certificates.
636
2018-12-20 21:02:33,206+01 [PAOS] DEBUG o.o.common.util.TR03112Utils:115 - Hash of the retrieved server certificate: 08198A75E92BCC93CDFF9383603D686B153B1C589ED3E0096A408F5E2E711C6C
637
2018-12-20 21:02:33,207+01 [PAOS] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 08198A75E92BCC93CDFF9383603D686B153B1C589ED3E0096A408F5E2E711C6C
638
2018-12-20 21:02:33,208+01 [PAOS] DEBUG o.o.common.util.TR03112Utils:61 - Checking SOP for https://www.fuehrungszeugnis.bund.de/ffw/npa-servlet/_FcslZNAQAKU80PqnEi3UQ/clientInvocation;jsessionid=2C03384CF32556E0AA74287E034FC7E8.nodevlp61081-02 and https://www.fuehrungszeugnis.bund.de/ffw.
639
2018-12-20 21:02:33,215+01 [PAOS] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Transmit.
640
2018-12-20 21:02:33,218+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
641
2018-12-20 21:02:33,218+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
642
2018-12-20 21:02:33,218+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
643
2018-12-20 21:02:33,219+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Transmit
644
2018-12-20 21:02:33,219+01 [PAOS] DEBUG o.o.i.s.wrapper.SingleThreadChannel:251 - Send APDU: 0022C1A40F800A04007F00070202040202830103
645
2018-12-20 21:02:33,274+01 [PAOS] DEBUG o.o.i.s.wrapper.SingleThreadChannel:254 - Receive APDU: 9000
646
2018-12-20 21:02:33,285+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
647
2018-12-20 21:02:33,285+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
648
2018-12-20 21:02:33,285+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
649
2018-12-20 21:02:33,348+01 [EAC-GUI] WARN  org.openecard.common.I18n:152 - Failed to load resource gui for lang de_DE.
650
2018-12-20 21:02:33,474+01 [EAC-GUI] DEBUG org.openecard.gui.swing.StepBar:97 - Selecting index 0, previous was -1.
651
2018-12-20 21:02:33,647+01 [EAC-GUI] WARN  org.openecard.common.I18n:152 - Failed to load resource swing for lang de_DE.
652
2018-12-20 21:02:33,808+01 [Swing-GUI-BG-Task] DEBUG o.o.s.protocol.eac.gui.CardMonitor:65 - Waiting for card to be removed.
653
2018-12-20 21:02:39,446+01 [AWT-EventQueue-0] DEBUG o.o.gui.swing.SwingNavigator:244 - Received event: Button.next
654
2018-12-20 21:02:39,453+01 [AWT-EventQueue-0] DEBUG org.openecard.gui.swing.StepFrame:257 - Trying to kill background task if it exists.
655
2018-12-20 21:02:39,453+01 [AWT-EventQueue-0] DEBUG org.openecard.gui.swing.StepFrame:260 - Killing background task.
656
2018-12-20 21:02:39,455+01 [Swing-GUI-BG-Task] DEBUG o.o.s.protocol.eac.gui.CardMonitor:76 - Card has not been removed.
657
2018-12-20 21:02:39,456+01 [AWT-EventQueue-0] DEBUG org.openecard.gui.swing.StepFrame:222 - Exchange result for step 'Anbieter'.
658
2018-12-20 21:02:39,457+01 [EAC-GUI] DEBUG o.o.gui.executor.ExecutionEngine:92 - Step PROTOCOL_EAC_GUI_STEP_CVC finished with result OK.
659
2018-12-20 21:02:39,460+01 [Swing-GUI-BG-Task] DEBUG org.openecard.gui.swing.StepFrame$1:276 - Background task has been terminated from the Swing GUI.
660
java.lang.InterruptedException: null
661
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1039)
662
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
663
	at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277)
664
	at org.openecard.common.util.Promise.deref(Promise.java:140)
665
	at org.openecard.common.util.Promise.deref(Promise.java:120)
666
	at org.openecard.sal.protocol.eac.gui.CardMonitor.call(CardMonitor.java:66)
667
	at org.openecard.sal.protocol.eac.gui.CardMonitor.call(CardMonitor.java:47)
668
	at org.openecard.gui.swing.StepFrame$1.run(StepFrame.java:272)
669
	at java.lang.Thread.run(Thread.java:748)
670
2018-12-20 21:02:39,478+01 [pool-2-thread-1] WARN  o.o.sal.protocol.eac.gui.CHATStep:131 - Removing community ID verification because of missing AAD.
671
2018-12-20 21:02:39,478+01 [pool-2-thread-1] WARN  o.o.sal.protocol.eac.gui.CHATStep:124 - Removing age verification because of missing or invalid AAD.
672
2018-12-20 21:02:39,481+01 [EAC-GUI] DEBUG o.o.gui.executor.ExecutionEngine:155 - Step Action PROTOCOL_EAC_GUI_STEP_CVC finished with result NEXT.
673
2018-12-20 21:02:39,482+01 [EAC-GUI] DEBUG o.o.gui.executor.ExecutionEngine:186 - Replacing after action with step.id=PROTOCOL_EAC_GUI_STEP_CHAT.
674
2018-12-20 21:02:39,547+01 [EAC-GUI] DEBUG org.openecard.gui.swing.StepBar:97 - Selecting index 1, previous was 0.
675
2018-12-20 21:02:39,614+01 [Swing-GUI-BG-Task] DEBUG o.o.s.protocol.eac.gui.CardMonitor:65 - Waiting for card to be removed.
676
2018-12-20 21:02:42,897+01 [AWT-EventQueue-0] DEBUG o.o.gui.swing.SwingNavigator:244 - Received event: Button.next
677
2018-12-20 21:02:42,902+01 [AWT-EventQueue-0] DEBUG org.openecard.gui.swing.StepFrame:257 - Trying to kill background task if it exists.
678
2018-12-20 21:02:42,903+01 [AWT-EventQueue-0] DEBUG org.openecard.gui.swing.StepFrame:260 - Killing background task.
679
2018-12-20 21:02:42,907+01 [Swing-GUI-BG-Task] DEBUG o.o.s.protocol.eac.gui.CardMonitor:76 - Card has not been removed.
680
2018-12-20 21:02:42,907+01 [AWT-EventQueue-0] DEBUG org.openecard.gui.swing.StepFrame:222 - Exchange result for step 'Angefragte Daten'.
681
2018-12-20 21:02:42,907+01 [Swing-GUI-BG-Task] DEBUG org.openecard.gui.swing.StepFrame$1:276 - Background task has been terminated from the Swing GUI.
682
java.lang.InterruptedException: null
683
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1039)
684
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
685
	at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277)
686
	at org.openecard.common.util.Promise.deref(Promise.java:140)
687
	at org.openecard.common.util.Promise.deref(Promise.java:120)
688
	at org.openecard.sal.protocol.eac.gui.CardMonitor.call(CardMonitor.java:66)
689
	at org.openecard.sal.protocol.eac.gui.CardMonitor.call(CardMonitor.java:47)
690
	at org.openecard.gui.swing.StepFrame$1.run(StepFrame.java:272)
691
	at java.lang.Thread.run(Thread.java:748)
692
2018-12-20 21:02:42,907+01 [EAC-GUI] DEBUG o.o.gui.executor.ExecutionEngine:92 - Step PROTOCOL_EAC_GUI_STEP_CHAT finished with result OK.
693
2018-12-20 21:02:42,922+01 [EAC-GUI] DEBUG o.o.gui.executor.ExecutionEngine:155 - Step Action PROTOCOL_EAC_GUI_STEP_CHAT finished with result NEXT.
694
2018-12-20 21:02:42,923+01 [EAC-GUI] DEBUG o.o.gui.executor.ExecutionEngine:186 - Replacing after action with step.id=PROTOCOL_EAC_GUI_STEP_PIN.
695
2018-12-20 21:02:42,924+01 [EAC-GUI] DEBUG org.openecard.gui.swing.StepBar:97 - Selecting index 2, previous was 1.
696
2018-12-20 21:02:42,991+01 [Swing-GUI-BG-Task] DEBUG o.o.s.protocol.eac.gui.CardMonitor:65 - Waiting for card to be removed.
697
2018-12-20 21:02:43,006+01 [Instant-Return-Thread-1] DEBUG o.o.gui.swing.SwingNavigator:244 - Received event: Button.next
698
2018-12-20 21:02:43,015+01 [Instant-Return-Thread-1] DEBUG org.openecard.gui.swing.StepFrame:257 - Trying to kill background task if it exists.
699
2018-12-20 21:02:43,015+01 [Instant-Return-Thread-1] DEBUG org.openecard.gui.swing.StepFrame:260 - Killing background task.
700
2018-12-20 21:02:43,015+01 [Instant-Return-Thread-1] DEBUG org.openecard.gui.swing.StepFrame:222 - Exchange result for step 'PIN-Eingabe'.
701
2018-12-20 21:02:43,015+01 [Swing-GUI-BG-Task] DEBUG o.o.s.protocol.eac.gui.CardMonitor:76 - Card has not been removed.
702
2018-12-20 21:02:43,016+01 [Swing-GUI-BG-Task] DEBUG org.openecard.gui.swing.StepFrame$1:276 - Background task has been terminated from the Swing GUI.
703
java.lang.InterruptedException: null
704
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1039)
705
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
706
	at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277)
707
	at org.openecard.common.util.Promise.deref(Promise.java:140)
708
	at org.openecard.common.util.Promise.deref(Promise.java:120)
709
	at org.openecard.sal.protocol.eac.gui.CardMonitor.call(CardMonitor.java:66)
710
	at org.openecard.sal.protocol.eac.gui.CardMonitor.call(CardMonitor.java:47)
711
	at org.openecard.gui.swing.StepFrame$1.run(StepFrame.java:272)
712
	at java.lang.Thread.run(Thread.java:748)
713
2018-12-20 21:02:43,016+01 [EAC-GUI] DEBUG o.o.gui.executor.ExecutionEngine:92 - Step PROTOCOL_EAC_GUI_STEP_PIN finished with result OK.
714
2018-12-20 21:02:43,049+01 [pool-4-thread-1] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type EstablishChannel.
715
2018-12-20 21:02:43,093+01 [pool-4-thread-1] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
716
2018-12-20 21:02:43,093+01 [pool-4-thread-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
717
2018-12-20 21:02:43,094+01 [pool-4-thread-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
718
2018-12-20 21:02:43,094+01 [pool-4-thread-1] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.EstablishChannel
719
2018-12-20 21:02:43,111+01 [pool-4-thread-1] DEBUG org.openecard.ifd.scio.IFD:1093 - executeCtrlCode request: 02470303157F4C12060904007F00070301020253050001139B00002D0330820329060A04007F00070301030101A10E0C0C442D547275737420476D6248A2181316687474703A2F2F7777772E642D74727573742E6E6574A3170C1542756E646573616D742066C3BC72204A757374697AA42A132868747470733A2F2F7777772E6675656872756E67737A6575676E69732E62756E642E64652F666677A58201D80C8201D44E616D652C20416E7363687269667420756E6420452D4D61696C2D4164726573736520646573204469656E737465616E626965746572733A0D0A42756E646573616D742066C3BC72204A757374697A0D0A4164656E61756572616C6C65652039392D3130330D0A353331313320426F6E6E0D0A72656769737465726175736B756E66742D6F6E6C696E654062666A2E62756E642E64650D0A0D0A4765736368C3A46674737A7765636B3A0D0A4F6E6C696E652D416E74726167206175662045727465696C756E6720766F6E2046C3BC6872756E67737A6575676E697373656E20756E6420476577657262657A656E7472616C72656769737465726175736BC3BC6E6674656E0D0A0D0A5A757374C3A46E6469676520446174656E73636875747A626568C3B67264653A0D0A4469652042756E64657362656175667472616774652066C3BC722064656E20446174656E73636875747A20756E642064696520496E666F726D6174696F6E7366726569686569740D0A4875736172656E73747261C39F652033300D0A353331313720426F6E6E0D0A303232382D3939373739392D300D0A706F73747374656C6C6540626664692E62756E642E64650D0A687474703A2F2F7777772E626664692E62756E642E64650D0AA781CF3181CC042008198A75E92BCC93CDFF9383603D686B153B1C589ED3E0096A408F5E2E711C6C042047D84367639AC114B7CE5BFCE6B7AA30CEA10A9D33101CC383268047F082417C042087942ED74E7BD9D8EC866D8D76CB4B8D71B5B6B4863B7D48A1586A8603B9627F04209B9D1DF98B9EE3B2C90E62DC501C5C68B5C97F1154316D55F420F57A6D345DBB0420C9910FA727FEEBC2A638810E5258A32C53E270B12D42C44C98A64E574B0E95DA0420F851E83B3B81D3E11F27E3B97BE79CFBDB344176493F70BDCB0A5CBA8C9089A8
720
2018-12-20 21:03:26,325+01 [IFD Watcher 0] DEBUG o.o.ifd.event.IfdEventRunner:262 - Found a card removed event (REINER SCT cyberJack RFID komfort (9394279424) 00 00).
721
2018-12-20 21:03:26,326+01 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_REMOVED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
722
2018-12-20 21:03:26,326+01 [IFD Watcher 0] DEBUG o.o.s.p.eac.gui.CardRemovedFilter:55 - Received CARD_REMOVED event.
723
2018-12-20 21:03:26,326+01 [IFD Watcher 0] INFO  o.o.s.p.eac.gui.CardRemovedFilter:63 - Card removed during processing of EAC GUI.
724
2018-12-20 21:03:26,327+01 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_REMOVED to EventCallback org.openecard.sal.protocol.eac.gui.CardMonitor@3565a21c.
725
2018-12-20 21:03:26,327+01 [Dispatcher Event 0] INFO  o.o.c.sal.state.SALStateCallback:75 - Remove ConnectionHandle from SAL.
726
ConnectionHandle:
727
  Session: EjRS8YywdxcQWtM990olOw
728
  ContextHandle: 72E59137FF7BAF326A55F2DC1982D331
729
  IFDName: REINER SCT cyberJack RFID komfort (9394279424) 00 00  SlotIndex: 0
730
2018-12-20 21:03:26,328+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:114 - Removing CardStateEntries based on connection handle.
731
ConnectionHandle:
732
  Session: EjRS8YywdxcQWtM990olOw
733
  ContextHandle: 72E59137FF7BAF326A55F2DC1982D331
734
  IFDName: REINER SCT cyberJack RFID komfort (9394279424) 00 00  SlotIndex: 0
735
2018-12-20 21:03:26,328+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:160 - Internal removeEntry function called with removeSlotHandles=true.
736
2018-12-20 21:03:26,330+01 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_REMOVED to EventCallback org.openecard.richclient.gui.Status@87a85e1.
737
2018-12-20 21:03:26,330+01 [IFD Watcher 0] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification CARD_REMOVED to EventCallback org.openecard.addon.EventHandler@7c469c48.
738
2018-12-20 21:03:26,339+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:165 - Removing entry from session map for channel session=EjRS8YywdxcQWtM990olOw.
739
2018-12-20 21:03:26,339+01 [Dispatcher Event 1] DEBUG org.openecard.richclient.gui.Status:378 - Event: CARD_REMOVED
740
2018-12-20 21:03:26,340+01 [Dispatcher Event 1] DEBUG org.openecard.richclient.gui.Status:388 - ConnectionHandle: ifd=REINER SCT cyberJack RFID komfort (9394279424) 00 00, slot=null, ctx=72E59137FF7BAF326A55F2DC1982D331
741
2018-12-20 21:03:26,340+01 [Dispatcher Event 1] DEBUG org.openecard.richclient.gui.Status:394 - RecognitionInfo: null
742
2018-12-20 21:03:26,341+01 [Dispatcher Event 1] DEBUG org.openecard.richclient.gui.Status:420 - Event sent has responsibility=true for this card.
743
2018-12-20 21:03:26,340+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:168 - Removing entry from context map for ctx=72E59137FF7BAF326A55F2DC1982D331.
744
2018-12-20 21:03:26,342+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:172 - Removing all entries for SlotHandles.
745
2018-12-20 21:03:26,342+01 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:201 - Detecting initial terminal status.
746
2018-12-20 21:03:26,344+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:176 - Removing entry for slot=2C332AAF2B51C1B4661D4E738A4F837E52EE9B9831220257.
747
2018-12-20 21:03:26,344+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:184 - Removing all protocol instances.
748
2018-12-20 21:03:26,344+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateEntry:172 - Removing 0 protocols from card state entry.
749
2018-12-20 21:03:26,344+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:187 - Removing entry from allEntries set.
750
2018-12-20 21:03:26,344+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:160 - Internal removeEntry function called with removeSlotHandles=true.
751
2018-12-20 21:03:26,350+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:165 - Removing entry from session map for channel session=EjRS8YywdxcQWtM990olOw.
752
2018-12-20 21:03:26,351+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:168 - Removing entry from context map for ctx=72E59137FF7BAF326A55F2DC1982D331.
753
2018-12-20 21:03:26,351+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:172 - Removing all entries for SlotHandles.
754
2018-12-20 21:03:26,351+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:176 - Removing entry for slot=2C332AAF2B51C1B4661D4E738A4F837E52EE9B9831220257.
755
2018-12-20 21:03:26,352+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:184 - Removing all protocol instances.
756
2018-12-20 21:03:26,352+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateEntry:172 - Removing 1 protocols from card state entry.
757
2018-12-20 21:03:26,352+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:146 - Trying to remove protocol org.openecard.addon.sal.SALProtocolProxy@67feb717.
758
2018-12-20 21:03:26,352+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:148 - Force removing protocol org.openecard.addon.sal.SALProtocolProxy@67feb717.
759
2018-12-20 21:03:26,352+01 [Dispatcher Event 0] DEBUG o.o.sal.protocol.eac.EACProtocol:71 - Destroying EAC protocol instance.
760
2018-12-20 21:03:26,352+01 [Dispatcher Event 0] DEBUG o.o.common.sal.state.CardStateMap:187 - Removing entry from allEntries set.
761
2018-12-20 21:03:26,347+01 [IFD Watcher 0] DEBUG o.o.scio.PCSCTerminals$PCSCWatcher:205 - Terminal='REINER SCT cyberJack RFID komfort (9394279424) 00 00' cardPresent=false
762
2018-12-20 21:03:26,349+01 [Dispatcher Event 3] INFO  o.o.s.protocol.eac.gui.CardMonitor:84 - Receiving card removed event.
763
2018-12-20 21:03:26,372+01 [pool-4-thread-1] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
764
2018-12-20 21:03:26,373+01 [pool-4-thread-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
765
2018-12-20 21:03:26,373+01 [pool-4-thread-1] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
766
2018-12-20 21:03:26,373+01 [pool-4-thread-1] ERROR o.o.s.p.eac.gui.PINStepAction:215 - An unknown error occured while trying to verify the PIN.
767
2018-12-20 21:03:26,374+01 [EAC-GUI] DEBUG o.o.gui.executor.ExecutionEngine:155 - Step Action PROTOCOL_EAC_GUI_STEP_PIN finished with result REPEAT.
768
2018-12-20 21:03:26,375+01 [EAC-GUI] DEBUG o.o.gui.executor.ExecutionEngine:186 - Replacing after action with step.id=PROTOCOL_EAC_GUI_STEP_ERROR.
769
2018-12-20 21:03:26,375+01 [EAC-GUI] DEBUG org.openecard.gui.swing.StepBar:97 - Selecting index 2, previous was 2.
770
2018-12-20 21:04:04,539+01 [AWT-EventQueue-0] DEBUG o.o.gui.swing.SwingNavigator:244 - Received event: Button.next
771
2018-12-20 21:04:04,542+01 [AWT-EventQueue-0] DEBUG org.openecard.gui.swing.StepFrame:257 - Trying to kill background task if it exists.
772
2018-12-20 21:04:04,542+01 [AWT-EventQueue-0] DEBUG org.openecard.gui.swing.StepFrame:222 - Exchange result for step 'Fehler'.
773
2018-12-20 21:04:04,543+01 [EAC-GUI] DEBUG o.o.gui.executor.ExecutionEngine:92 - Step PROTOCOL_EAC_GUI_STEP_ERROR finished with result OK.
774
2018-12-20 21:04:04,549+01 [EAC-GUI] DEBUG o.o.gui.executor.ExecutionEngine:155 - Step Action PROTOCOL_EAC_GUI_STEP_ERROR finished with result CANCEL.
775
2018-12-20 21:04:04,549+01 [EAC-GUI] INFO  o.o.gui.executor.ExecutionEngine:179 - StepAction was canceled.
776
2018-12-20 21:04:04,549+01 [EAC-GUI] DEBUG o.o.gui.executor.ExecutionEngine:229 - Closing UserConsentNavigator.
777
2018-12-20 21:04:04,551+01 [PAOS] DEBUG o.o.sal.protocol.eac.PACEStep:327 - Received error object from GUI.
778
org.openecard.common.WSHelper$WSException: http://www.bsi.bund.de/ecard/api/1.1/resultminor/al/common#unknownError
779
  ==> Failed to transmit control command to the terminal 'REINER SCT cyberJack RFID komfort (9394279424) 00 00'.
780
	at org.openecard.common.ECardException.makeException(ECardException.java:64)
781
	at org.openecard.common.WSHelper$WSException.<init>(WSHelper.java:47)
782
	at org.openecard.common.WSHelper.checkResult(WSHelper.java:69)
783
	at org.openecard.sal.protocol.eac.gui.PINStepAction.perform(PINStepAction.java:191)
784
	at org.openecard.gui.executor.StepActionCallable.call(StepActionCallable.java:58)
785
	at org.openecard.gui.executor.StepActionCallable.call(StepActionCallable.java:37)
786
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
787
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
788
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
789
	at java.lang.Thread.run(Thread.java:748)
790
2018-12-20 21:04:04,551+01 [PAOS] DEBUG o.o.sal.protocol.eac.EACProtocol:100 - Checking if EAC protocol is finished.
791
2018-12-20 21:04:04,552+01 [EAC-GUI] DEBUG o.o.sal.protocol.eac.PACEStep:283 - EAC GUI returned with CANCEL or INTERRUPTED.
792
2018-12-20 21:04:04,552+01 [PAOS] DEBUG o.o.sal.protocol.eac.EACProtocol:120 - EAC authentication finished=false.
793
2018-12-20 21:04:04,595+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
794
2018-12-20 21:04:04,595+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
795
2018-12-20 21:04:04,595+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
796
2018-12-20 21:04:04,608+01 [PAOS] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request (before adding content):
797
  POST /ecardpaos/paosreceiver HTTP/1.1
798
  Connection: keep-alive
799
  User-Agent: Open eCard App/1.3.0
800
  Host: eid2.eid-service.de:443
801
  PAOS: ver="urn:liberty:paos:2006-08" ;"urn:iso:std:iso-iec:24727:tech:schema:Transmit";"http://www.bsi.bund.de/ecard/api/1.0#InitializeFramework";"urn:iso:std:iso-iec:24727:tech:schema:StartSession";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationEndSession";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationList";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationServiceList";"urn:iso:std:iso-iec:24727:tech:schema:CardApplicationServiceDescribe";"urn:iso:std:iso-iec:24727:tech:schema:DataSetList";"urn:iso:std:iso-iec:24727:tech:schema:DataSetSelect";"urn:iso:std:iso-iec:24727:tech:schema:DSIList";"urn:iso:std:iso-iec:24727:tech:schema:DSIWrite";"urn:iso:std:iso-iec:24727:tech:schema:DSIRead";"urn:iso:std:iso-iec:24727:tech:schema:Encipher";"urn:iso:std:iso-iec:24727:tech:schema:Decipher";"urn:iso:std:iso-iec:24727:tech:schema:GetRandom";"urn:iso:std:iso-iec:24727:tech:schema:Sign";"urn:iso:std:iso-iec:24727:tech:schema:VerifySignature";"urn:iso:std:iso-iec:24727:tech:schema:VerifyCertificate";"urn:iso:std:iso-iec:24727:tech:schema:DIDList";"urn:iso:std:iso-iec:24727:tech:schema:DIDGet";"urn:iso:std:iso-iec:24727:tech:schema:DIDAuthenticate";"urn:iso:std:iso-iec:24727:tech:schema:ACLList";"urn:iso:std:iso-iec:24727:tech:schema:Hash"
802
  Accept: text/xml, application/xml, application/vnd.paos+xml
803

    
804
2018-12-20 21:04:04,631+01 [PAOS] DEBUG org.openecard.transport.paos.PAOS:268 - Message sent:
805
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
806
<Envelope xmlns="http://schemas.xmlsoap.org/soap/envelope/">
807
  <Header>
808
    <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">
809
      <Version>urn:liberty:paos:2006-08</Version>
810
      <EndpointReference>
811
        <Address>http://www.projectliberty.org/2006/01/role/paos</Address>
812
        <MetaData>
813
          <ServiceType>http://www.bsi.bund.de/ecard/api/1.1/PAOS/GetNextCommand</ServiceType>
814
        </MetaData>
815
      </EndpointReference>
816
    </PAOS>
817
    <ReplyTo xmlns="http://www.w3.org/2005/03/addressing">
818
      <Address>http://www.projectliberty.org/2006/02/role/paos</Address>
819
    </ReplyTo>
820
    <RelatesTo xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:c4c68538-8b34-427e-9d18-03d4bd86afe4</RelatesTo>
821
    <MessageID xmlns="http://www.w3.org/2005/03/addressing">urn:uuid:940c4c49-c506-46d6-9e0b-9e9de655cae9</MessageID>
822
  </Header>
823
  <Body>
824
    <ns3:DIDAuthenticateResponse xmlns="urn:oasis:names:tc:dss:1.0:core:schema" 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="http://www.bsi.bund.de/ecard/api/1.1" 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="http://uri.etsi.org/01903/v1.3.2#" xmlns:ns9="urn:oasis:names:tc:dss-x:1.0:profiles:verificationreport:schema#" Profile="http://www.bsi.bund.de/ecard/api/1.1">
825
      <Result>
826
        <ResultMajor>http://www.bsi.bund.de/ecard/api/1.1/resultmajor#error</ResultMajor>
827
        <ResultMinor>http://www.bsi.bund.de/ecard/api/1.1/resultminor/al/common#unknownError</ResultMinor>
828
        <ResultMessage xml:lang="en">Failed to transmit control command to the terminal 'REINER SCT cyberJack RFID komfort (9394279424) 00 00'.</ResultMessage>
829
      </Result>
830
      <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"/>
831
    </ns3:DIDAuthenticateResponse>
832
  </Body>
833
</Envelope>
834

    
835
2018-12-20 21:04:04,631+01 [PAOS] DEBUG org.openecard.transport.paos.PAOS:363 - Sending HTTP request.
836
2018-12-20 21:04:04,639+01 [PAOS] INFO  o.o.c.tls.ClientCertPSKTlsClient:257 - TLS warning received.
837
2018-12-20 21:04:04,639+01 [PAOS] INFO  o.o.c.tls.ClientCertPSKTlsClient:258 - TLS(WARN): Close [close_notify=0] --> Unknown error.
838
2018-12-20 21:04:04,639+01 [PAOS] INFO  o.o.c.tls.ClientCertPSKTlsClient:239 - TLS warning sent.
839
2018-12-20 21:04:04,639+01 [PAOS] INFO  o.o.c.tls.ClientCertPSKTlsClient:241 - TLS(WARN): Close [close_notify=0] --> Connection closed
840
2018-12-20 21:04:04,640+01 [PAOS] WARN  org.openecard.transport.paos.PAOS:433 - PAOS server closed the connection. Trying to connect again.
841
2018-12-20 21:04:04,640+01 [PAOS] DEBUG org.openecard.transport.paos.PAOS:470 - Opening connection to PAOS server.
842
2018-12-20 21:04:04,645+01 [PAOS] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for java. Trying next one.
843
2018-12-20 21:04:04,647+01 [PAOS] DEBUG o.o.c.t.proxy.ProxySettingsLoader$1:80 - Firefox settings folder is {0}
844
2018-12-20 21:04:04,661+01 [PAOS] WARN  o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found.
845
2018-12-20 21:04:04,661+01 [PAOS] WARN  o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found.
846
2018-12-20 21:04:04,661+01 [PAOS] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for firefox. Trying next one.
847
2018-12-20 21:04:04,661+01 [PAOS] WARN  o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found.
848
2018-12-20 21:04:04,662+01 [PAOS] WARN  o.o.c.t.proxy.ProxySettingsLoader$1:86 - Gnome settings: {0} not found.
849
2018-12-20 21:04:04,662+01 [PAOS] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for desktop. Trying next one.
850
2018-12-20 21:04:04,662+01 [PAOS] INFO  o.o.c.t.proxy.ProxySettingsLoader$1:83 - No proxy found for env. Trying next one.
851
2018-12-20 21:04:04,662+01 [PAOS] DEBUG o.o.crypto.tls.proxy.ProxySettings:133 - Selecting proxy: DIRECT
852
2018-12-20 21:04:04,662+01 [PAOS] DEBUG o.o.crypto.tls.proxy.ProxySettings:168 - Using proxy (DIRECT) to obtain socket.
853
2018-12-20 21:04:06,825+01 [PAOS] DEBUG o.o.c.tls.verify.HostnameVerifier:126 - Comparing connection hostname against certificate hostname: [eid2.eid-service.de] [eid2.eid-service.de]
854
2018-12-20 21:04:07,709+01 [PAOS] ERROR o.o.c.tls.ClientCertPSKTlsClient:260 - TLS error received.
855
2018-12-20 21:04:07,710+01 [PAOS] ERROR o.o.c.tls.ClientCertPSKTlsClient:261 - TLS(FATAL): MAC of record invalid [bad_record_mac=20] --> Unknown error.
856
2018-12-20 21:04:07,717+01 [PAOS] DEBUG o.o.common.util.HandlerUtils:125 - Found ConnectionHandle in object of type CardApplicationDisconnect.
857
2018-12-20 21:04:07,724+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
858
2018-12-20 21:04:07,724+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
859
2018-12-20 21:04:07,725+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
860
2018-12-20 21:04:07,725+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.CardApplicationDisconnect
861
2018-12-20 21:04:07,726+01 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:135 - Removing CardStateEntries for slot=2C332AAF2B51C1B4661D4E738A4F837E52EE9B9831220257.
862
2018-12-20 21:04:07,726+01 [PAOS] DEBUG o.o.common.sal.state.CardStateMap:114 - Removing CardStateEntries based on connection handle.
863
ConnectionHandle:
864
  ContextHandle: 72E59137FF7BAF326A55F2DC1982D331
865
  SlotHandle: 2C332AAF2B51C1B4661D4E738A4F837E52EE9B9831220257
866
2018-12-20 21:04:07,727+01 [PAOS] DEBUG o.o.common.util.HandlerUtils:145 - Found SlotHandle in object of type Disconnect.
867
2018-12-20 21:04:07,729+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:105 - Sending API_CALL_STARTED event.
868
2018-12-20 21:04:07,729+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
869
2018-12-20 21:04:07,730+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_STARTED to EventCallback org.openecard.addon.EventHandler@7c469c48.
870
2018-12-20 21:04:07,730+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:114 - Delivering message of type: iso.std.iso_iec._24727.tech.schema.Disconnect
871
2018-12-20 21:04:07,731+01 [PAOS] WARN  org.openecard.ifd.scio.IFD:825 - No card available in the requested terminal.
872
org.openecard.ifd.scio.wrapper.NoSuchChannel: No channel for slot '2C332AAF2B51C1B4661D4E738A4F837E52EE9B9831220257' available.
873
	at org.openecard.ifd.scio.wrapper.ChannelManager.getSlaveChannel(ChannelManager.java:119)
874
	at org.openecard.ifd.scio.IFD.disconnect(IFD.java:777)
875
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
876
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
877
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
878
	at java.lang.reflect.Method.invoke(Method.java:498)
879
	at org.openecard.transport.dispatcher.Service.invoke(Service.java:192)
880
	at org.openecard.transport.dispatcher.MessageDispatcher.deliver(MessageDispatcher.java:116)
881
	at org.openecard.transport.dispatcher.MessageDispatcher.safeDeliver(MessageDispatcher.java:135)
882
	at org.openecard.sal.TinySAL.cardApplicationDisconnect(TinySAL.java:481)
883
	at org.openecard.sal.SelectorSAL.cardApplicationDisconnect(SelectorSAL.java:320)
884
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
885
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
886
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
887
	at java.lang.reflect.Method.invoke(Method.java:498)
888
	at org.openecard.transport.dispatcher.Service.invoke(Service.java:192)
889
	at org.openecard.transport.dispatcher.MessageDispatcher.deliver(MessageDispatcher.java:116)
890
	at org.openecard.transport.dispatcher.MessageDispatcher.safeDeliver(MessageDispatcher.java:135)
891
	at org.openecard.binding.tctoken.TCTokenHandler.disconnectHandle(TCTokenHandler.java:272)
892
	at org.openecard.binding.tctoken.PAOSTask.call(PAOSTask.java:114)
893
	at org.openecard.binding.tctoken.PAOSTask.call(PAOSTask.java:53)
894
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
895
	at java.lang.Thread.run(Thread.java:748)
896
2018-12-20 21:04:07,736+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
897
2018-12-20 21:04:07,736+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
898
2018-12-20 21:04:07,736+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
899
2018-12-20 21:04:07,741+01 [PAOS] DEBUG o.o.t.dispatcher.MessageDispatcher:122 - Sending API_CALL_FINISHED event.
900
2018-12-20 21:04:07,742+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.common.sal.state.SALStateCallback@8909f18.
901
2018-12-20 21:04:07,742+01 [PAOS] DEBUG o.o.c.event.EventDispatcherImpl:140 - Sending event notification API_CALL_FINISHED to EventCallback org.openecard.addon.EventHandler@7c469c48.
902
2018-12-20 21:04:07,743+01 [Thread-7] ERROR o.o.binding.tctoken.TCTokenHandler:431 - org.openecard.transport.paos.PAOSConnectionException: Es konnte keine Verbindung zum eID-Server aufgebaut werden.
903
java.util.concurrent.ExecutionException: org.openecard.transport.paos.PAOSConnectionException: Es konnte keine Verbindung zum eID-Server aufgebaut werden.
904
	at java.util.concurrent.FutureTask.report(FutureTask.java:122)
905
	at java.util.concurrent.FutureTask.get(FutureTask.java:192)
906
	at org.openecard.binding.tctoken.TCTokenHandler.waitForTask(TCTokenHandler.java:425)
907
	at org.openecard.binding.tctoken.TCTokenHandler.processBinding(TCTokenHandler.java:234)
908
	at org.openecard.binding.tctoken.TCTokenHandler.handleActivate(TCTokenHandler.java:337)
909
	at org.openecard.addons.activate.ActivateAction.processTcToken(ActivateAction.java:409)
910
	at org.openecard.addons.activate.ActivateAction.processRequest(ActivateAction.java:265)
911
	at org.openecard.addons.activate.ActivateAction.checkRequestParameters(ActivateAction.java:246)
912
	at org.openecard.addons.activate.ActivateAction.execute(ActivateAction.java:127)
913
	at org.openecard.addon.bind.AppPluginActionProxy.execute(AppPluginActionProxy.java:55)
914
	at org.openecard.control.binding.http.handler.HttpAppPluginActionHandler.handle(HttpAppPluginActionHandler.java:127)
915
	at org.openecard.apache.http.protocol.HttpService.doService(HttpService.java:437)
916
	at org.openecard.apache.http.protocol.HttpService.handleRequest(HttpService.java:342)
917
	at org.openecard.control.binding.http.HttpService$1.run(HttpService.java:132)
918
Caused by: org.openecard.transport.paos.PAOSConnectionException: Failed to establish a connection to the eID-Server.
919
	at org.openecard.transport.paos.PAOS.openHttpStream(PAOS.java:476)
920
	at org.openecard.transport.paos.PAOS.sendStartPAOS(PAOS.java:338)
921
	at org.openecard.binding.tctoken.PAOSTask.call(PAOSTask.java:112)
922
	at org.openecard.binding.tctoken.PAOSTask.call(PAOSTask.java:53)
923
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
924
	at java.lang.Thread.run(Thread.java:748)
925
Caused by: org.openecard.bouncycastle.tls.TlsFatalAlertReceived: bad_record_mac(20)
926
	at org.openecard.bouncycastle.tls.TlsProtocol.handleAlertMessage(TlsProtocol.java:151)
927
	at org.openecard.bouncycastle.tls.TlsProtocol.processAlertQueue(TlsProtocol.java:505)
928
	at org.openecard.bouncycastle.tls.TlsProtocol.processRecord(TlsProtocol.java:370)
929
	at org.openecard.bouncycastle.tls.RecordStream.readRecord(RecordStream.java:317)
930
	at org.openecard.bouncycastle.tls.TlsProtocol.safeReadRecord(TlsProtocol.java:621)
931
	at org.openecard.bouncycastle.tls.TlsProtocol.blockForHandshake(TlsProtocol.java:273)
932
	at org.openecard.bouncycastle.tls.TlsClientProtocol.connect(TlsClientProtocol.java:104)
933
	at org.openecard.binding.tctoken.TlsConnectionHandler.createNewTlsConnection(TlsConnectionHandler.java:255)
934
	at org.openecard.binding.tctoken.TlsConnectionHandler.createTlsConnection(TlsConnectionHandler.java:236)
935
	at org.openecard.binding.tctoken.TlsConnectionHandler.createTlsConnection(TlsConnectionHandler.java:230)
936
	at org.openecard.transport.paos.PAOS.openHttpStream(PAOS.java:471)
937
	... 5 common frames omitted
938
2018-12-20 21:04:07,744+01 [Thread-7] ERROR o.o.binding.tctoken.TCTokenHandler:350 - java.util.concurrent.ExecutionException: org.openecard.transport.paos.PAOSConnectionException: Es konnte keine Verbindung zum eID-Server aufgebaut werden.
939
org.openecard.transport.paos.PAOSException: java.util.concurrent.ExecutionException: org.openecard.transport.paos.PAOSConnectionException: Es konnte keine Verbindung zum eID-Server aufgebaut werden.
940
	at org.openecard.binding.tctoken.TCTokenHandler.waitForTask(TCTokenHandler.java:438)
941
	at org.openecard.binding.tctoken.TCTokenHandler.processBinding(TCTokenHandler.java:234)
942
	at org.openecard.binding.tctoken.TCTokenHandler.handleActivate(TCTokenHandler.java:337)
943
	at org.openecard.addons.activate.ActivateAction.processTcToken(ActivateAction.java:409)
944
	at org.openecard.addons.activate.ActivateAction.processRequest(ActivateAction.java:265)
945
	at org.openecard.addons.activate.ActivateAction.checkRequestParameters(ActivateAction.java:246)
946
	at org.openecard.addons.activate.ActivateAction.execute(ActivateAction.java:127)
947
	at org.openecard.addon.bind.AppPluginActionProxy.execute(AppPluginActionProxy.java:55)
948
	at org.openecard.control.binding.http.handler.HttpAppPluginActionHandler.handle(HttpAppPluginActionHandler.java:127)
949
	at org.openecard.apache.http.protocol.HttpService.doService(HttpService.java:437)
950
	at org.openecard.apache.http.protocol.HttpService.handleRequest(HttpService.java:342)
951
	at org.openecard.control.binding.http.HttpService$1.run(HttpService.java:132)
952
Caused by: java.util.concurrent.ExecutionException: org.openecard.transport.paos.PAOSConnectionException: Es konnte keine Verbindung zum eID-Server aufgebaut werden.
953
	at java.util.concurrent.FutureTask.report(FutureTask.java:122)
954
	at java.util.concurrent.FutureTask.get(FutureTask.java:192)
955
	at org.openecard.binding.tctoken.TCTokenHandler.waitForTask(TCTokenHandler.java:425)
956
	... 11 common frames omitted
957
Caused by: org.openecard.transport.paos.PAOSConnectionException: Failed to establish a connection to the eID-Server.
958
	at org.openecard.transport.paos.PAOS.openHttpStream(PAOS.java:476)
959
	at org.openecard.transport.paos.PAOS.sendStartPAOS(PAOS.java:338)
960
	at org.openecard.binding.tctoken.PAOSTask.call(PAOSTask.java:112)
961
	at org.openecard.binding.tctoken.PAOSTask.call(PAOSTask.java:53)
962
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
963
	at java.lang.Thread.run(Thread.java:748)
964
Caused by: org.openecard.bouncycastle.tls.TlsFatalAlertReceived: bad_record_mac(20)
965
	at org.openecard.bouncycastle.tls.TlsProtocol.handleAlertMessage(TlsProtocol.java:151)
966
	at org.openecard.bouncycastle.tls.TlsProtocol.processAlertQueue(TlsProtocol.java:505)
967
	at org.openecard.bouncycastle.tls.TlsProtocol.processRecord(TlsProtocol.java:370)
968
	at org.openecard.bouncycastle.tls.RecordStream.readRecord(RecordStream.java:317)
969
	at org.openecard.bouncycastle.tls.TlsProtocol.safeReadRecord(TlsProtocol.java:621)
970
	at org.openecard.bouncycastle.tls.TlsProtocol.blockForHandshake(TlsProtocol.java:273)
971
	at org.openecard.bouncycastle.tls.TlsClientProtocol.connect(TlsClientProtocol.java:104)
972
	at org.openecard.binding.tctoken.TlsConnectionHandler.createNewTlsConnection(TlsConnectionHandler.java:255)
973
	at org.openecard.binding.tctoken.TlsConnectionHandler.createTlsConnection(TlsConnectionHandler.java:236)
974
	at org.openecard.binding.tctoken.TlsConnectionHandler.createTlsConnection(TlsConnectionHandler.java:230)
975
	at org.openecard.transport.paos.PAOS.openHttpStream(PAOS.java:471)
976
	... 5 common frames omitted
977
2018-12-20 21:04:07,747+01 [Thread-7] INFO  o.o.binding.tctoken.ResourceContext:207 - Trying to load resource from: https://eid1.eid-service.de:443/gov_autent/async?refID=_553c069918ad166b6beeb0490bb06e900f9be4b5
978
2018-12-20 21:04:07,747+01 [Thread-7] DEBUG o.o.crypto.tls.proxy.ProxySettings:133 - Selecting proxy: DIRECT
979
2018-12-20 21:04:07,748+01 [Thread-7] DEBUG o.o.crypto.tls.proxy.ProxySettings:168 - Using proxy (DIRECT) to obtain socket.
980
2018-12-20 21:04:08,884+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:244 - Performing TLS handshake.
981
2018-12-20 21:04:09,577+01 [Thread-7] DEBUG o.o.c.tls.verify.HostnameVerifier:126 - Comparing connection hostname against certificate hostname: [eid1.eid-service.de] [eid1.eid-service.de]
982
2018-12-20 21:04:10,794+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:246 - TLS handshake performed.
983
2018-12-20 21:04:10,795+01 [Thread-7] INFO  o.o.common.util.TR03112Utils:107 - Checking certificate hash of https://eid1.eid-service.de:443 against list of communication certificates.
984
2018-12-20 21:04:10,798+01 [Thread-7] DEBUG o.o.common.util.TR03112Utils:115 - Hash of the retrieved server certificate: 08198A75E92BCC93CDFF9383603D686B153B1C589ED3E0096A408F5E2E711C6C
985
2018-12-20 21:04:10,800+01 [Thread-7] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 08198A75E92BCC93CDFF9383603D686B153B1C589ED3E0096A408F5E2E711C6C
986
2018-12-20 21:04:10,800+01 [Thread-7] DEBUG o.o.common.util.TR03112Utils:61 - Checking SOP for https://eid1.eid-service.de:443/gov_autent/async?refID=_553c069918ad166b6beeb0490bb06e900f9be4b5 and https://www.fuehrungszeugnis.bund.de/ffw.
987
2018-12-20 21:04:10,801+01 [Thread-7] ERROR o.o.common.util.TR03112Utils:72 - SOP violated; the hosts do not match.
988
2018-12-20 21:04:10,802+01 [Thread-7] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request:
989
  GET /gov_autent/async?refID=_553c069918ad166b6beeb0490bb06e900f9be4b5 HTTP/1.1
990
  Connection: keep-alive
991
  User-Agent: Open eCard App/1.3.0
992
  Host: eid1.eid-service.de:443
993
  Accept: text/xml, */*;q=0.8
994
  Accept-Charset: utf-8, *;q=0.8
995

    
996
2018-12-20 21:04:10,803+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:267 - Sending HTTP request.
997
2018-12-20 21:04:11,220+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:270 - HTTP response received.
998
2018-12-20 21:04:11,221+01 [Thread-7] DEBUG o.o.transport.httpcore.HttpUtils:112 - HTTP Response:
999
  HTTP/1.1 302 Found
1000
  Cache-Control: HTTP/1.1 302 Moved Temporarilyno-cache, no-store
1001
  Server: HTTP/1.1 302 Moved Temporarilyno-cache, no-storeApache-Coyote/1.1
1002
  Content-Security-Policy: HTTP/1.1 302 Moved Temporarilyno-cache, no-storeApache-Coyote/1.1default-src 'self'
1003
  Pragma: HTTP/1.1 302 Moved Temporarilyno-cache, no-storeApache-Coyote/1.1default-src 'self'no-cache
1004
  Content-Length: 0
1005
  Date: HTTP/1.1 302 Moved Temporarilyno-cache, no-storeApache-Coyote/1.1default-src 'self'no-cache0Thu, 20 Dec 2018 20:04:10 GMT
1006
  Location: https://www.fuehrungszeugnis.bund.de/ffw/npa-servlet/_FcslZNAQAKU80PqnEi3UQ/serverResponse;jsessionid=2C03384CF32556E0AA74287E034FC7E8.nodevlp61081-02?SAMLResponse=hVLBcpswEP0VDXdACLBlNXaGceyJp43TJHYOuWQELLZaLBFJ2Jl8fQUJbcaH9MIMq919b997F5evhxodQRuh5NSLAuwhkIUqhdxNve1m6VPvcnZh%2BKEmDbsH0yhpALkhadh7deq1WjLFjTBM8gMYZgv2kN38YCTArNHKqkLVHroCY4XktgfaW9sYFoan0ymoWtjrVu7MG7Q7KUyQt7IMSgir6hTKhvsG9LEGGz4vC1M%2FrbO77PuW4p8vciHi7V3YPYMeuH37ZcB014hySuY4jmkyX8YkTUcLnGXjhNDxAsfJcj5e0ECqEo51M4owjXxMPLS6mnrPFSZVDBPuTwBP%2FCSZlD5PCPEjnORpGiVJHqeuVQ6QG%2BWGKC1GeRzRcZ5XeToiOE7peIJpOipSmuJuwJgWVtJYLu3UIziifkR8gjcEM5ywCAcTHD956HFww%2BnnfWjP%2BmH9WfivdefGydJp7c0GrUGUUeA%2BvZ6iACcxS5L4Iux9%2FED46%2FWD5bY1Z79zpxd65HULX6O7G92wy8tL61wHPZzRsPe153tyZfxcwwFkR6oPz0FIpbs%2Blm0317f3q6dss7pdP2%2FXy9V69XC9uPLC2Qf3z2vPGN%2B4MPAdzDZ7QLy1e6XFW59B5JJZuEdUKY30O1H0Xxf7TqHBIC6V3TtHeNFvq7Q6IFdARS1AWpSD2%2BsgUXcMsuo3SFRw6epIdFaWwRn3gehZ%2Bd%2BJQ9pmfwA%3D&RelayState=_88c6b3187bbfb5620358790856c58505&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%23rsa-sha256&Signature=lfdqqETMUY2jdNBzehxNaSheE%2FT8YvJDmE%2By%2B0p382B1zXIOmJyPIdHcHe2dCRwr530PtiMqEr%2Fi2ytE8vs%2FPORfN0Vvr2Lnkj2ew%2FCgTWM74QIaq430oj3%2BLtftQfft6vm2ziACKxBIOikYiRy0ANBJzOtlxYg9bqmqy9qJ%2BsY%2F3GAo4N4Gaanu1LQ6Utdr4OF4FjbLBJtHVJe7OGYQCMFqpRANaZ3x3vCXAeWotNNqj7i05HCKkuLFElHhfsTpGl3lmC7RyHZZ2h%2FLd6tl9hUSQy50GEDNMoC4UYrRApMoSPrYUKYmVKZhO9BHz9ohHnI9TuA4TzPFhk%2B%2BFjEx3A%3D%3D
1007

    
1008

    
1009
2018-12-20 21:04:11,222+01 [Thread-7] INFO  o.o.c.t.ClientCertDefaultTlsClient:298 - TLS warning sent.
1010
2018-12-20 21:04:11,223+01 [Thread-7] INFO  o.o.c.t.ClientCertDefaultTlsClient:300 - TLS(WARN): Close [close_notify=0] --> Connection closed
1011
2018-12-20 21:04:11,224+01 [Thread-7] INFO  o.o.binding.tctoken.ResourceContext:207 - Trying to load resource from: https://www.fuehrungszeugnis.bund.de/ffw/npa-servlet/_FcslZNAQAKU80PqnEi3UQ/serverResponse;jsessionid=2C03384CF32556E0AA74287E034FC7E8.nodevlp61081-02?SAMLResponse=hVLBcpswEP0VDXdACLBlNXaGceyJp43TJHYOuWQELLZaLBFJ2Jl8fQUJbcaH9MIMq919b997F5evhxodQRuh5NSLAuwhkIUqhdxNve1m6VPvcnZh%2BKEmDbsH0yhpALkhadh7deq1WjLFjTBM8gMYZgv2kN38YCTArNHKqkLVHroCY4XktgfaW9sYFoan0ymoWtjrVu7MG7Q7KUyQt7IMSgir6hTKhvsG9LEGGz4vC1M%2FrbO77PuW4p8vciHi7V3YPYMeuH37ZcB014hySuY4jmkyX8YkTUcLnGXjhNDxAsfJcj5e0ECqEo51M4owjXxMPLS6mnrPFSZVDBPuTwBP%2FCSZlD5PCPEjnORpGiVJHqeuVQ6QG%2BWGKC1GeRzRcZ5XeToiOE7peIJpOipSmuJuwJgWVtJYLu3UIziifkR8gjcEM5ywCAcTHD956HFww%2BnnfWjP%2BmH9WfivdefGydJp7c0GrUGUUeA%2BvZ6iACcxS5L4Iux9%2FED46%2FWD5bY1Z79zpxd65HULX6O7G92wy8tL61wHPZzRsPe153tyZfxcwwFkR6oPz0FIpbs%2Blm0317f3q6dss7pdP2%2FXy9V69XC9uPLC2Qf3z2vPGN%2B4MPAdzDZ7QLy1e6XFW59B5JJZuEdUKY30O1H0Xxf7TqHBIC6V3TtHeNFvq7Q6IFdARS1AWpSD2%2BsgUXcMsuo3SFRw6epIdFaWwRn3gehZ%2Bd%2BJQ9pmfwA%3D&RelayState=_88c6b3187bbfb5620358790856c58505&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%23rsa-sha256&Signature=lfdqqETMUY2jdNBzehxNaSheE%2FT8YvJDmE%2By%2B0p382B1zXIOmJyPIdHcHe2dCRwr530PtiMqEr%2Fi2ytE8vs%2FPORfN0Vvr2Lnkj2ew%2FCgTWM74QIaq430oj3%2BLtftQfft6vm2ziACKxBIOikYiRy0ANBJzOtlxYg9bqmqy9qJ%2BsY%2F3GAo4N4Gaanu1LQ6Utdr4OF4FjbLBJtHVJe7OGYQCMFqpRANaZ3x3vCXAeWotNNqj7i05HCKkuLFElHhfsTpGl3lmC7RyHZZ2h%2FLd6tl9hUSQy50GEDNMoC4UYrRApMoSPrYUKYmVKZhO9BHz9ohHnI9TuA4TzPFhk%2B%2BFjEx3A%3D%3D
1012
2018-12-20 21:04:11,225+01 [Thread-7] DEBUG o.o.crypto.tls.proxy.ProxySettings:133 - Selecting proxy: DIRECT
1013
2018-12-20 21:04:11,226+01 [Thread-7] DEBUG o.o.crypto.tls.proxy.ProxySettings:168 - Using proxy (DIRECT) to obtain socket.
1014
2018-12-20 21:04:11,724+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:244 - Performing TLS handshake.
1015
2018-12-20 21:04:12,309+01 [Thread-7] DEBUG o.o.c.tls.verify.HostnameVerifier:126 - Comparing connection hostname against certificate hostname: [www.fuehrungszeugnis.bund.de] [www.fuehrungszeugnis.bund.de]
1016
2018-12-20 21:04:13,660+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:246 - TLS handshake performed.
1017
2018-12-20 21:04:13,661+01 [Thread-7] INFO  o.o.common.util.TR03112Utils:107 - Checking certificate hash of https://www.fuehrungszeugnis.bund.de against list of communication certificates.
1018
2018-12-20 21:04:13,663+01 [Thread-7] DEBUG o.o.common.util.TR03112Utils:115 - Hash of the retrieved server certificate: 9B9D1DF98B9EE3B2C90E62DC501C5C68B5C97F1154316D55F420F57A6D345DBB
1019
2018-12-20 21:04:13,665+01 [Thread-7] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 08198A75E92BCC93CDFF9383603D686B153B1C589ED3E0096A408F5E2E711C6C
1020
2018-12-20 21:04:13,665+01 [Thread-7] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 47D84367639AC114B7CE5BFCE6B7AA30CEA10A9D33101CC383268047F082417C
1021
2018-12-20 21:04:13,666+01 [Thread-7] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 87942ED74E7BD9D8EC866D8D76CB4B8D71B5B6B4863B7D48A1586A8603B9627F
1022
2018-12-20 21:04:13,667+01 [Thread-7] DEBUG o.o.common.util.TR03112Utils:120 - CommCertificate: 9B9D1DF98B9EE3B2C90E62DC501C5C68B5C97F1154316D55F420F57A6D345DBB
1023
2018-12-20 21:04:13,667+01 [Thread-7] DEBUG o.o.common.util.TR03112Utils:61 - Checking SOP for https://eid1.eid-service.de:443/gov_autent/async?refID=_553c069918ad166b6beeb0490bb06e900f9be4b5 and https://www.fuehrungszeugnis.bund.de/ffw.
1024
2018-12-20 21:04:13,667+01 [Thread-7] ERROR o.o.common.util.TR03112Utils:72 - SOP violated; the hosts do not match.
1025
2018-12-20 21:04:13,668+01 [Thread-7] DEBUG o.o.transport.httpcore.HttpUtils:81 - HTTP Request:
1026
  GET /ffw/npa-servlet/_FcslZNAQAKU80PqnEi3UQ/serverResponse;jsessionid=2C03384CF32556E0AA74287E034FC7E8.nodevlp61081-02?SAMLResponse=hVLBcpswEP0VDXdACLBlNXaGceyJp43TJHYOuWQELLZaLBFJ2Jl8fQUJbcaH9MIMq919b997F5evhxodQRuh5NSLAuwhkIUqhdxNve1m6VPvcnZh%2BKEmDbsH0yhpALkhadh7deq1WjLFjTBM8gMYZgv2kN38YCTArNHKqkLVHroCY4XktgfaW9sYFoan0ymoWtjrVu7MG7Q7KUyQt7IMSgir6hTKhvsG9LEGGz4vC1M%2FrbO77PuW4p8vciHi7V3YPYMeuH37ZcB014hySuY4jmkyX8YkTUcLnGXjhNDxAsfJcj5e0ECqEo51M4owjXxMPLS6mnrPFSZVDBPuTwBP%2FCSZlD5PCPEjnORpGiVJHqeuVQ6QG%2BWGKC1GeRzRcZ5XeToiOE7peIJpOipSmuJuwJgWVtJYLu3UIziifkR8gjcEM5ywCAcTHD956HFww%2BnnfWjP%2BmH9WfivdefGydJp7c0GrUGUUeA%2BvZ6iACcxS5L4Iux9%2FED46%2FWD5bY1Z79zpxd65HULX6O7G92wy8tL61wHPZzRsPe153tyZfxcwwFkR6oPz0FIpbs%2Blm0317f3q6dss7pdP2%2FXy9V69XC9uPLC2Qf3z2vPGN%2B4MPAdzDZ7QLy1e6XFW59B5JJZuEdUKY30O1H0Xxf7TqHBIC6V3TtHeNFvq7Q6IFdARS1AWpSD2%2BsgUXcMsuo3SFRw6epIdFaWwRn3gehZ%2Bd%2BJQ9pmfwA%3D&RelayState=_88c6b3187bbfb5620358790856c58505&SigAlg=http%3A%2F%2Fwww.w3.org%2F2001%2F04%2Fxmldsig-more%23rsa-sha256&Signature=lfdqqETMUY2jdNBzehxNaSheE%2FT8YvJDmE%2By%2B0p382B1zXIOmJyPIdHcHe2dCRwr530PtiMqEr%2Fi2ytE8vs%2FPORfN0Vvr2Lnkj2ew%2FCgTWM74QIaq430oj3%2BLtftQfft6vm2ziACKxBIOikYiRy0ANBJzOtlxYg9bqmqy9qJ%2BsY%2F3GAo4N4Gaanu1LQ6Utdr4OF4FjbLBJtHVJe7OGYQCMFqpRANaZ3x3vCXAeWotNNqj7i05HCKkuLFElHhfsTpGl3lmC7RyHZZ2h%2FLd6tl9hUSQy50GEDNMoC4UYrRApMoSPrYUKYmVKZhO9BHz9ohHnI9TuA4TzPFhk%2B%2BFjEx3A%3D%3D HTTP/1.1
1027
  Connection: keep-alive
1028
  User-Agent: Open eCard App/1.3.0
1029
  Host: www.fuehrungszeugnis.bund.de
1030
  Accept: text/xml, */*;q=0.8
1031
  Accept-Charset: utf-8, *;q=0.8
1032

    
1033
2018-12-20 21:04:13,668+01 [Thread-7] DEBUG o.o.binding.tctoken.ResourceContext:267 - Sending HTTP request.
1034
2018-12-20 21:04:14,271+01 [AWT-EventQueue-0] DEBUG o.openecard.richclient.gui.Status$1:182 - Shutdown button pressed.
1035
2018-12-20 21:04:14,274+01 [AWT-EventQueue-0] DEBUG o.o.sal.protocol.eac.EACProtocol:71 - Destroying EAC protocol instance.
1036
2018-12-20 21:04:14,276+01 [IFD Watcher 0] WARN  org.openecard.ifd.scio.IFD:559 - Unknown SCIO error occured during wait call.
1037
org.openecard.common.ifd.scio.SCIOException: Wait interrupted by another thread.
1038
	at org.openecard.scio.PCSCTerminals$PCSCWatcher.sleep(PCSCTerminals.java:347)
1039
	at org.openecard.scio.PCSCTerminals$PCSCWatcher.internalWait(PCSCTerminals.java:397)
1040
	at org.openecard.scio.PCSCTerminals$PCSCWatcher.waitForChange(PCSCTerminals.java:267)
1041
	at org.openecard.ifd.scio.EventWatcher.call(EventWatcher.java:95)
1042
	at org.openecard.ifd.scio.EventWatcher.call(EventWatcher.java:49)
1043
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
1044
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
1045
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
1046
	at java.lang.Thread.run(Thread.java:748)
1047
2018-12-20 21:04:14,278+01 [IFD Watcher 0] WARN  o.o.ifd.event.IfdEventRunner:134 - IFD Wait returned with error.
1048
org.openecard.common.WSHelper$WSException: http://www.bsi.bund.de/ecard/api/1.1/resultminor/ifdl/unknownError
1049
  ==> Unknown SCIO error occured during wait call.
1050
	at org.openecard.common.ECardException.makeException(ECardException.java:64)
1051
	at org.openecard.common.WSHelper$WSException.<init>(WSHelper.java:47)
1052
	at org.openecard.common.WSHelper.checkResult(WSHelper.java:69)
1053
	at org.openecard.ifd.event.IfdEventManager.wait(IfdEventManager.java:125)
1054
	at org.openecard.ifd.event.IfdEventRunner.run(IfdEventRunner.java:130)
1055
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
1056
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
1057
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
1058
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
1059
	at java.lang.Thread.run(Thread.java:748)
1060
2018-12-20 21:04:14,278+01 [IFD Watcher 0] INFO  o.o.ifd.event.IfdEventRunner:142 - Event thread interrupted.
1061
java.lang.InterruptedException: sleep interrupted
1062
	at java.lang.Thread.sleep(Native Method)
1063
	at org.openecard.ifd.event.IfdEventRunner.run(IfdEventRunner.java:137)
1064
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
1065
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
1066
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
1067
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
1068
	at java.lang.Thread.run(Thread.java:748)
1069
2018-12-20 21:04:14,279+01 [IFD Watcher 0] INFO  o.o.ifd.event.IfdEventRunner:144 - Stopping IFD event thread.
(3-3/3)