On 13/02/2019 03:43, Johanes Soetanto wrote:
Hi Emmanuel,
Do you need the full log spit out by ApacheDS or just partial ?
I'(d like to get a bit more logs, before the error. Here, we just have
the last elements of the Handshake.
Is below enough? After login, I notice the log pause a bit before exception
thrown.
p | NioProcessor-9, READ: TLSv1.2 Change Cipher Spec, length = 1
ap | update handshake state: change_cipher_spec
ap | upcoming handshake states: client finished[20]
ap | [Raw read]: length = 5
ap | 0000: 16 03 03 00 60 ....`
ap | [Raw read]: length = 96
ap | 0000: 8D 97 2A 97 BD 10 FC 8A D7 5E 0A CC 3E F9 B3 00
..*......^..>...
ap | 0010: 05 2E D5 65 E1 92 D7 75 51 8B 7E 16 EC E2 33 B1
...e...uQ.....3.
ap | 0020: AF 2F 9B 90 BB AD 14 67 EC 7F 7C 93 08 89 FD D3
./.....g........
ap | 0030: 85 9D 89 46 A3 53 8C 3B CB 7C F0 04 AE D7 52 C3
...F.S.;......R.
ap | 0040: EB D0 C3 EA EA B1 E4 64 CB F8 C8 10 32 09 3D 0D
.......d....2.=.
ap | 0050: B8 45 19 AB E3 73 C4 E7 43 21 F8 DD 6B 41 17 35
.E...s..C!..kA.5
ap | NioProcessor-9, READ: TLSv1.2 Handshake, length = 96
ap | Padded plaintext after DECRYPTION: len = 96
ap | 0000: 2B F9 26 98 C1 87 6F 9F 2A FF 8A 3E 28 F3 F4 A8
+.&...o.*..>(...
ap | 0010: 14 00 00 0C 82 8B 03 77 B1 5A DF D9 F7 45 DF 93
.......w.Z...E..
ap | 0020: F4 21 01 56 65 87 B3 C7 AA 12 C2 87 76 C6 CB B8
.!.Ve.......v...
ap | 0030: F3 50 B9 CC 85 08 21 F1 42 5D 68 38 2C F1 06 6F
.P....!.B]h8,..o
ap | 0040: BF F3 25 F9 AF B0 A5 76 40 9F 2A 46 33 1D C5 E6 ..%....v@
.*F3...
ap | 0050: 0F 0F 0F 0F 0F 0F 0F 0F 0F 0F 0F 0F 0F 0F 0F 0F
................
ap | check handshake state: finished[20]
ap | update handshake state: finished[20]
ap | *** Finished
ap | verify_data: { 130, 139, 3, 119, 177, 90, 223, 217, 247, 69, 223,
147 }
ap | ***
ap | [read] MD5 and SHA1 hashes: len = 16
ap | 0000: 14 00 00 0C 82 8B 03 77 B1 5A DF D9 F7 45 DF 93
.......w.Z...E..
ap | [Raw read (bb)]: length = 117
This is the first block of application data (0x17), TLS 1.2 (0x03 0x03)
112 bytes long (0x00 0x70). It's obviously encrypted.
ap | 0000: 17 03 03 00 70 05 86 9C 3F F1 2A A2 1D E8 FD 9C
....p...?.*.....
ap | 0010: DF 4F 9F 1E 18 58 E3 8E B8 B6 48 EC F7 2B 56 40
.O...X....H..+V@
ap | 0020: 62 47 EA 57 91 30 C7 80 78 F9 E4 8E 04 E2 29 7F
bG.W.0..x.....).
ap | 0030: 56 48 16 3E A4 B0 E0 10 C1 F8 A3 AB E2 C9 A0 C0
VH.>............
ap | 0040: 5C 1D 56 F3 B0 68 BE D7 26 28 19 04 91 8A 32 4A
\.V..h..&(....2J
ap | 0050: 73 42 DC 4D 34 1F 9C 4A 9E 6B B0 69 0C C1 74 DD
sB.M4..J.k.i..t.
ap | 0060: 7E 82 3F A4 E7 28 F3 AF 6B 72 B9 E2 5D 75 A8 DE
..?..(..kr..]u..
ap | 0070: 1B C9 09 3E 02 ...>.
ap | Padded plaintext after DECRYPTION: len = 112
ap | 0000: 03 B0 06 22 55 4D CE C6 A4 17 52 44 BC 40 F5 70
..."[email protected]
The following bytes are the BindRequest, with user 'uid=admin,ou=system'
and password 'Pa55word393'. This BindRequest is correct.
The problem is that it's encapsulated into blocks of meaningless data
(03 B0 06 22 55 4D CE C6 A4 17 52 44 BC 40 F5 70 before and 1C D7 B2 BC
63 F4 D0 B9 0C 83 58 8B 5C DD 15 C1 46 15 69 5D 12 54 21 2C 39 6F 87 48
88 AA 30 AD 85 9A D5 21 19 79 76 68 D2 D3 95 45 6F 06 06 06 06 06 06 06
after). I have no idea what those are...
ap | 0010: 30 27 02 01 01 60 22 02 01 03 04 13 75 69 64 3D
0'...`".....uid=
ap | 0020: 61 64 6D 69 6E 2C 6F 75 3D 73 79 73 74 65 6D 80
admin,ou=system.
ap | 0030: 08 50 61 35 35 77 6F 72 64 33 39 33 1C D7 B2 BC
.Pa55word393....
ap | 0040: 63 F4 D0 B9 0C 83 58 8B 5C DD 15 C1 46 15 69 5D
c.....X.\...F.i]
ap | 0050: 12 54 21 2C 39 6F 87 48 88 AA 30 AD 85 9A D5 21
.T!,9o.H..0....!
ap | 0060: 19 79 76 68 D2 D3 95 45 6F 06 06 06 06 06 06 06
.yvh...Eo.......
ap | [Raw write (bb)]: length = 0
ap | [Raw write (bb)]: length = 0
ap | [Raw write (bb)]: length = 0
ap | [Raw write (bb)]: length = 0
ap | [Raw write (bb)]: length = 0
ap | [Raw write (bb)]: length = 0
ap | [Raw write (bb)]: length = 0
ap | [Raw write (bb)]: length = 0
ap | [Raw write (bb)]: length = 0
ap | [Raw write (bb)]: length = 0
ap | [Raw write (bb)]: length = 0
ap | [Raw write (bb)]: length = 0
ap | [02:32:00] WARN
[org.apache.directory.server.ldap.LdapProtocolHandler] - Unexpected
exception forcing session to close: sending disconnect notice to client.
ap | java.lang.OutOfMemoryError: Java heap space
ap | at java.nio.HeapByteBuffer.<init>(HeapByteBuffer.java:57)
ap | at java.nio.ByteBuffer.allocate(ByteBuffer.java:335)
ap | at
org.apache.mina.core.buffer.SimpleBufferAllocator.allocateNioBuffer(SimpleBufferAllocator.java:42)
ap | at
org.apache.mina.core.buffer.AbstractIoBuffer.capacity(AbstractIoBuffer.java:185)
ap | at
org.apache.mina.filter.ssl.SslHandler.handshake(SslHandler.java:597)
ap | at
org.apache.mina.filter.ssl.SslHandler.messageReceived(SslHandler.java:353)
ap | at
org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:516)
ap | at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:650)
ap | at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:49)
ap | at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:1141)
ap | at
org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:122)
ap | at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:650)
ap | at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:643)
ap | at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:539)
ap | at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$1200(AbstractPollingIoProcessor.java:68)
ap | at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.process(AbstractPollingIoProcessor.java:1242)
ap | at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.process(AbstractPollingIoProcessor.java:1231)
ap | at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:683)
ap | at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
ap | at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
ap | at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
ap | at java.lang.Thread.run(Thread.java:748)
ap | NioProcessor-9, called closeOutbound()
ap | NioProcessor-9, closeOutboundInternal()
ap | NioProcessor-9, SEND TLSv1.2 ALERT: warning, description =
close_notify
ap | Padded plaintext before ENCRYPTION: len = 80
ap | 0000: C6 3B 7A D5 95 38 52 CB 15 7A 79 16 18 26 46 A1
.;z..8R..zy..&F.
ap | 0010: 01 00 AC 27 31 D2 F3 52 C0 D4 A2 CE D2 72 F1 F9
...'1..R.....r..
ap | 0020: BB 4F 01 A0 F0 EE E2 E6 0A 96 61 BA 34 B2 38 D4
.O........a.4.8.
ap | 0030: C4 2A E1 2E 3F C5 20 C1 DB 22 2C 71 D4 A0 0F 63 .*..?.
..",q...c
ap | 0040: A0 57 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D
.W..............
ap | NioProcessor-9, WRITE: TLSv1.2 Alert, length = 80
ap | [02:32:00] WARN
[org.apache.directory.server.ldap.LdapProtocolHandler] - Unexpected
exception forcing session to close: sending disconnect notice to client.
ap | java.lang.OutOfMemoryError: Java heap space
ap | at java.nio.HeapByteBuffer.<init>(HeapByteBuffer.java:57)
ap | at java.nio.ByteBuffer.allocate(ByteBuffer.java:335)
ap | at org.apache.mina.core.buffer.SimpleBufferAllocator.allocate
During PingFederate connection check I also see this in the log, I'm not
quite sure if it is related at all as well.
It's just an Alert sent during the TLS protocol.
apacheds-standard_1 | 0040: A5 B4 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D 0D
0D ................
apacheds-standard_1 | pool-7-thread-3, WRITE: TLSv1.2 Alert, length = 80
apacheds-standard_1 | [Raw write]: length = 85
apacheds-standard_1 | 0000: 15 03 03 00 50 0C CE F8 7B EB 50 3F A5 55 C0
08 ....P.....P?.U..
apacheds-standard_1 | 0010: 2F D4 D9 0F 2E A0 86 C7 19 FB 79 4E 75 CE C0
79 /.........yNu..y
apacheds-standard_1 | 0020: 18 BF AC CF FF 9D EA 16 D5 D3 AC 63 54 8E 3E
B7 ...........cT.>.
apacheds-standard_1 | 0030: F4 69 76 FE 1C 29 44 82 7F 3B B4 D4 9C 7F 75
09 .iv..)D..;....u.
apacheds-standard_1 | 0040: A5 7D 76 D0 80 CF 18 8E 2C 9D B3 9D 31 0E 8B
5A ..v.....,...1..Z
apacheds-standard_1 | 0050: 09 B0 FC D9 D5
.....
apacheds-standard_1 | NioProcessor-9, called closeInbound()
apacheds-standard_1 | NioProcessor-9, fatal error: 80: Inbound closed
before receiving peer's close_notify: possible truncation attack?
apacheds-standard_1 | javax.net.ssl.SSLException: Inbound closed before
receiving peer's close_notify: possible truncation attack?
apacheds-standard_1 | %% Invalidated: [Session-3,
TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384]
apacheds-standard_1 | NioProcessor-9, SEND TLSv1.2 ALERT: fatal,
description = internal_error
apacheds-standard_1 | NioProcessor-9, Exception sending alert:
java.io.IOException: writer side was already closed.
apacheds-standard_1 | NioProcessor-9, called closeOutbound()
apacheds-standard_1 | NioProcessor-9, closeOutboundInternal()
Regards,
Johanes
I would be interested to get the logs you get when running the server in
your computer, instead of a container.
