PN_TRACE_FRM=1 java -Djava.security.auth.login.config=/var/dtests/node_data/gssapi/msgqe.com/qpid-jms-client/alice.login.config  -Dsun.security.krb5.debug=true -Djava.security.krb5.conf=/var/dtests/node_data/gssapi/msgqe.com/msgqe_krb5.conf  -jar /var/dtests/node_data/clients/aac1.jar receiver  --log-msgs dict --broker-uri "amqp://amq-server-6x.msgqe.com:5672?amqp.saslMechanisms=GSSAPI&sasl.options.protocol=amqp&sasl.options.serverName=amq-server-6x.msgqe.com" --address lala --t 2
Debug is  true storeKey false useTicketCache true useKeyTab false doNotPrompt false ticketCache is null isInitiator true KeyTab is null refreshKrb5Config is false principal is null tryFirstPass is false useFirstPass is false storePass is false clearPass is false
Acquire TGT from Cache
>>>KinitOptions cache name is /tmp/krb5cc_0
>>>DEBUG <CCacheInputStream>  client principal is amqp/amq-server-6x.msgqe.com@MSGQE.COM
>>>DEBUG <CCacheInputStream> server principal is krbtgt/MSGQE.COM@MSGQE.COM
>>>DEBUG <CCacheInputStream> key type: 18
>>>DEBUG <CCacheInputStream> auth time: Mon Jan 15 13:34:48 CET 2018
>>>DEBUG <CCacheInputStream> start time: Mon Jan 15 13:34:48 CET 2018
>>>DEBUG <CCacheInputStream> end time: Tue Jan 16 13:34:48 CET 2018
>>>DEBUG <CCacheInputStream> renew_till time: null
>>> CCacheInputStream: readFlags()  FORWARDABLE; INITIAL; PRE_AUTH;
>>>DEBUG <CCacheInputStream>  client principal is amqp/amq-server-6x.msgqe.com@MSGQE.COM
Java config name: /var/dtests/node_data/gssapi/msgqe.com/msgqe_krb5.conf
Loaded from Java config
>>>DEBUG <CCacheInputStream> server principal is X-CACHECONF:/krb5_ccache_conf_data/fast_avail/krbtgt/MSGQE.COM@MSGQE.COM@MSGQE.COM
>>>DEBUG <CCacheInputStream> key type: 0
>>>DEBUG <CCacheInputStream> auth time: Thu Jan 01 01:00:00 CET 1970
>>>DEBUG <CCacheInputStream> start time: null
>>>DEBUG <CCacheInputStream> end time: Thu Jan 01 01:00:00 CET 1970
>>>DEBUG <CCacheInputStream> renew_till time: null
>>> CCacheInputStream: readFlags() 
Principal is amqp/amq-server-6x.msgqe.com@MSGQE.COM
Commit Succeeded 

Found ticket for amqp/amq-server-6x.msgqe.com@MSGQE.COM to go to krbtgt/MSGQE.COM@MSGQE.COM expiring on Tue Jan 16 13:34:48 CET 2018
Entered Krb5Context.initSecContext with state=STATE_NEW
Found ticket for amqp/amq-server-6x.msgqe.com@MSGQE.COM to go to krbtgt/MSGQE.COM@MSGQE.COM expiring on Tue Jan 16 13:34:48 CET 2018
Service ticket not found in the subject
>>> Credentials acquireServiceCreds: same realm
Using builtin default etypes for default_tgs_enctypes
default etypes for default_tgs_enctypes: 18 17 16 23.
>>> CksumType: sun.security.krb5.internal.crypto.RsaMd5CksumType
>>> EType: sun.security.krb5.internal.crypto.Aes256CtsHmacSha1EType
>>> KdcAccessibility: reset
>>> KrbKdcReq send: kdc=ipa-server.msgqe.com UDP:88, timeout=30000, number of retries =3, #bytes=694
>>> KDCCommunication: kdc=ipa-server.msgqe.com UDP:88, timeout=30000,Attempt =1, #bytes=694
>>> KrbKdcReq send: #bytes read=708
>>> KdcAccessibility: remove ipa-server.msgqe.com:88
>>> EType: sun.security.krb5.internal.crypto.Aes256CtsHmacSha1EType
>>> KrbApReq: APOptions are 00000000 00000000 00000000 00000000
>>> EType: sun.security.krb5.internal.crypto.Aes256CtsHmacSha1EType
Krb5Context setting mySeqNumber to: 1036549365
Krb5Context setting peerSeqNumber to: 0
Created InitSecContextToken:
0000: 01 00 6E 82 02 76 30 82   02 72 A0 03 02 01 05 A1  ..n..v0..r......
0010: 03 02 01 0E A2 07 03 05   00 00 00 00 00 A3 82 01  ................
0020: 74 61 82 01 70 30 82 01   6C A0 03 02 01 05 A1 0B  ta..p0..l.......
0030: 1B 09 4D 53 47 51 45 2E   43 4F 4D A2 2A 30 28 A0  ..MSGQE.COM.*0(.
0040: 03 02 01 00 A1 21 30 1F   1B 04 61 6D 71 70 1B 17  .....!0...amqp..
0050: 61 6D 71 2D 73 65 72 76   65 72 2D 36 78 2E 6D 73  amq-server-6x.ms
0060: 67 71 65 2E 63 6F 6D A3   82 01 2A 30 82 01 26 A0  gqe.com...*0..&.
0070: 03 02 01 12 A1 03 02 01   01 A2 82 01 18 04 82 01  ................
0080: 14 8F 09 8C 38 20 D0 9F   33 D5 19 DF 48 64 B5 25  ....8 ..3...Hd.%
0090: 35 F5 50 8B 2B 5C 09 13   01 AC 06 C0 A6 F2 B4 A5  5.P.+\..........
00A0: C3 48 B7 1D D6 48 61 FE   29 12 BE 68 94 CB 39 E3  .H...Ha.)..h..9.
00B0: CE 7E BE B3 7F 59 2D 4C   E5 9E C3 43 05 16 8D D3  .....Y-L...C....
00C0: 61 E7 B3 C1 20 49 91 21   8B 7E 49 55 32 41 A0 1B  a... I.!..IU2A..
00D0: 19 B8 38 F8 F5 EF 24 62   E7 27 D7 65 93 7E A4 4C  ..8...$b.'.e...L
00E0: 4E 12 A4 47 10 64 B2 A2   6B A9 3A 54 CD 45 45 C2  N..G.d..k.:T.EE.
00F0: 9F 0B 89 A5 F1 4E 73 67   49 B5 BC 44 B9 58 DB F7  .....NsgI..D.X..
0100: 2C 6D 22 2E DD 18 8B B0   B3 AF 22 4B C3 7A 55 72  ,m"......."K.zUr
0110: BC 14 E2 98 96 D2 DF 3C   EA 6A E2 E4 72 68 66 1B  .......<.j..rhf.
0120: DE 85 70 00 DF 9B 75 00   3C 92 3F B4 D7 FB A8 A0  ..p...u.<.?.....
0130: 22 B5 DF C0 4D 14 E9 95   30 0E 47 0C 19 FC E1 88  "...M...0.G.....
0140: 46 75 4B 15 FD B9 CE 6D   81 31 6C 84 1D 66 9B BC  FuK....m.1l..f..
0150: EF A8 58 66 66 29 38 C0   22 F9 9C 0E 80 91 60 8A  ..Xff)8.".....`.
0160: B9 D7 92 F0 AF D0 29 21   17 35 2E 65 CB E2 65 73  ......)!.5.e..es
0170: AD BC BC D2 7D EC 51 0C   73 7D 47 69 2F 69 84 A1  ......Q.s.Gi/i..
0180: C7 CE 4A 32 8C 68 6F 96   41 CF FF AD 96 6A F1 B2  ..J2.ho.A....j..
0190: A9 0A 73 A7 41 A4 81 E4   30 81 E1 A0 03 02 01 12  ..s.A...0.......
01A0: A2 81 D9 04 81 D6 26 7E   ED 0C 7F 83 0F 00 4C 5E  ......&.......L^
01B0: 82 7E 1A 06 77 89 26 7E   08 AA 9C CD 0A B0 45 1C  ....w.&.......E.
01C0: 00 BE 1C 28 F2 12 4E 19   6E 41 92 4D E8 9E 7A 84  ...(..N.nA.M..z.
01D0: AE 6F D8 00 BB 48 53 4B   97 60 3E 5B 39 C7 17 A5  .o...HSK.`>[9...
01E0: 44 42 12 1A 21 CC 34 61   64 3A D2 83 8E 38 FB 57  DB..!.4ad:...8.W
01F0: 94 92 D5 ED 50 5C AF 6B   49 7C 41 FE 30 D9 E9 24  ....P\.kI.A.0..$
0200: 22 54 0F 49 1D 06 3F E3   E9 6B 7B F2 26 6C 73 01  "T.I..?..k..&ls.
0210: CE 12 87 0C E1 7A 12 E5   86 5B E9 04 82 00 66 D3  .....z...[....f.
0220: 83 9C 7D 0F 2B E8 1A 7D   47 F0 AB 95 E9 B0 8B 9F  ....+...G.......
0230: 57 FB 72 7B D1 54 DD 9E   3B C9 A5 CB 2E 81 62 10  W.r..T..;.....b.
0240: 66 AB 68 C0 FD 11 70 F5   14 50 8E 38 C8 2D D6 86  f.h...p..P.8.-..
0250: 57 28 3D C7 A6 40 5A 04   D9 0E 67 BB 0E 8D D8 A6  W(=..@Z...g.....
0260: AF DD 94 97 A4 C1 45 DD   57 33 3C 9E C3 6E EF 0B  ......E.W3<..n..
0270: 19 0A 39 84 D8 85 90 E7   A6 F5 62 C5              ..9.......b.

13:35:40,862 ERROR Error while creating session! Request to open resource AmqpConnection { ID:c817fbb2-bd77-48be-8410-424b07e9ae44:1 } timed out
org.apache.qpid.jms.JmsOperationTimedOutException: Request to open resource AmqpConnection { ID:c817fbb2-bd77-48be-8410-424b07e9ae44:1 } timed out
	at org.apache.qpid.jms.provider.amqp.builders.AmqpResourceBuilder.createException(AmqpResourceBuilder.java:208)
	at org.apache.qpid.jms.provider.amqp.AmqpProvider$22.run(AmqpProvider.java:1360)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

2018-01-15 09:36:35.899766 +0100 SERVER (trace) Accepting connection on 0.0.0.0:amqp
2018-01-15 09:36:35.906303 +0100 SERVER (trace) [1] Accepting incoming connection from  to 0.0.0.0:amqp
2018-01-15 09:36:35.906438 +0100 POLICY (trace) ALLOW Connection '1.2.3.4' based on global connection count. nConnections= 1
2018-01-15 09:36:35.906461 +0100 SERVER (info) Accepted connection to 0.0.0.0:amqp from 1.2.3.4:60698
2018-01-15 09:36:36.131539 +0100 SERVER (trace) [1]:  <- SASL
2018-01-15 09:36:36.131590 +0100 SERVER (trace) [1]:  -> SASL
2018-01-15 09:36:36.171556 +0100 SERVER (trace) [1]:0 -> @sasl-mechanisms(64) [sasl-server-mechanisms=@PN_SYMBOL[:GSSAPI]]
2018-01-15 09:36:36.974258 +0100 SERVER (trace) [1]:0 <- @sasl-init(65) [mechanism=:GSSAPI, initial-response=b"`\x82\x02@\x06\x09*\x86H\x86\xf7\x12\x01\x02\x02\x01\x00n\x82\x02/0\x82\x02+\xa0\x03\x02\x01\x05\xa1\x03\x02\x01\x0e\xa2\x07\x03\x05\x00\x00\x00\x00\x00\xa3\x82\x01Ea\x82\x01A0\x82\x01=\xa0\x03\x02\x01\x05\xa1\x0b\x1b\x09MSGQE.COM\xa2*0(\xa0\x03\x02\x01\x00\xa1!0\x1f\x1b\x04amqp\x1b\x17amq-server-6x.msgqe.com\xa3\x81\xfc0\x81\xf9\xa0\x03\x02\x01\x12\xa1\x03\x02\x01\x01\xa2\x81\xec\x04\x81\xe9\x0fjr\xa4\xae\xb3JG5\xc1\x15\xaa\x11c\x876\x1a\xdd\x11\x85\xaa\xea\x91\x05\xfdOn\x94I\xff) \x00\xf6wt\xfcbw<II\xdd\x97\x14\xee\x18\x86"mUn\xa1G\x8a_e\x16B\x9f\xa7o\x94\xdd_f\x00\xa5:\xb6\xa1\x1a\xad\x01\x92\x98I>\x97\x8b\xd9Q\xa1\xc2\xe6(\xb6\xb1\x8d\x85\xfc\xf0\xf3#o\xa1M\xf4M6>\xacg\x03\x9f\xf5K\x0a\x94\x11\xaf\xe9v\xa9\xbc\xfc.~\x18\x11\x9d\xb6#\xf1\xeb \xf2\xaf\xcfO\xe7\\xf4T\xc5"\xaf\xf8\xca`C\xf5\xbb\xba2\x8d\xf2\x04T\x8e t\xf9\xb1e\xd4&\xe91\x0d\xb9\xf2\xfd,B}\x91\xd5\x0bs\x9f`\xf1\x0e\xe1\xd9,\x031\xcc\xd9\xa4g\xae,\xbc\xdf\xe4k\xf8(\xd3\x0e:Y\x06BS\xb3\x99\xc7\x07\xbb\x8b\xbc\x0c\xe4\xc7:\xcf\x098\x91\xd0Ed\xba\xab\xc6\x10\xcd\x7fE~S\x8b\x99\xc9\xe1\xa2\x83\x16\x9e\xa4\x81\xcc0\x81\xc9\xa0\x03\x02\x01\x12\xa2\x81\xc1\x04\x81\xbe\x8c\x17\xa7tb\x1c\xca\x1a\xc7\x80_\xca\xcd\x91]\xe5\x884\xb4\xaap\x04\x18:o\xda\xb5\xf3\xf1\x9f\x0e\xd10hD\xee\xf3\xbb\x11\xd6\xc1\xb7\xd0\x15E\x89\xba]\x9d\xcf\xc2\x95Q!ue\xb6\x13%\x0bA} \xba\xb9P%\xa4\x8c\x13\x9c7:\x19\x9c\x1d}(\xcc\x07\x10B%\x1d0\xb7\xab~<\xa7\x89\xce\x7f`Mq1\x91&W\xcb\xe1;\x0eeg\xc5:\x98\xc9z*\xf31\xf5^[wK1}\x134\xdef\xd7nd\xabx\xf1\x05]\x16\xb4\xa3\x83\x08\xb5\x04(b\x9e\xdf\x80\xcb\x9a\x9e\x9b"\xc2\xf3b\xe7\x0f\xfb\x9c\xa4\xdf\\x00R"\x85~\x17\xbc\x8d\xf4\xc9\xee\x82\x8b\xcf3'\xda\x09\xf4\x85}O\xbe8\x89\x09\xc9\xa3\x9a(", hostname="amq-server-6x.msgqe.com"]
[30352] 1516005397.259247: Decrypted AP-REQ with server principal amqp/amq-server-6x.msgqe.com@MSGQE.COM: aes256-cts/00A4
[30352] 1516005397.259276: AP-REQ ticket: alice@MSGQE.COM -> amqp/amq-server-6x.msgqe.com@MSGQE.COM, session key aes256-cts/0CF7
[30352] 1516005397.281153: Negotiated enctype based on authenticator: aes256-cts
[30352] 1516005397.281171: Authenticator contains subkey: aes256-cts/046E
2018-01-15 09:36:37.281745 +0100 SERVER (trace) [1]:0 -> @sasl-challenge(66) [challenge=b""]
2018-01-15 09:37:05.939674 +0100 SERVER (trace) [1]:  <- EOS
2018-01-15 09:37:05.939711 +0100 SERVER (info) Connection from 1.2.3.4:60698 (to 0.0.0.0:amqp) failed: amqp:connection:framing-error connection aborted
2018-01-15 09:37:05.939722 +0100 SERVER (trace) [1]:  -> EOS
2018-01-15 09:37:05.939764 +0100 POLICY (debug) Connection '1.2.3.4:60698' closed with resources n_sessions=0, n_senders=0, n_receivers=0. nConnections= 0.