search

inejge / ldap3

A pure-Rust LDAP library using the Tokio stack
Apache License 2.0
220 stars 38 forks source link

WARN:ldap3::protocol: discarding frame with unmatched msgid: -128 #21

Closed sindreij closed 6 years ago

sindreij commented 6 years ago

I am facing a problem using ldap3. I have a test that does lots of ldap call to Active Directory, and on a random (I think) call, it just blocks. This is the output when i set RUST_LOG:

[...snip...]
DEBUG:ldap_integrationtests: Create user 50.
DEBUG:tokio_core::reactor: loop poll - Duration { secs: 0, nanos: 8926 }
DEBUG:tokio_core::reactor: loop time - Instant { tv_sec: 3023957, tv_nsec: 564581156 }
DEBUG:tokio_core::reactor: scheduling direction for: 0
DEBUG:tokio_core::reactor: blocking
DEBUG:tokio_core::reactor: scheduling direction for: 0
DEBUG:tokio_core::reactor: blocking
DEBUG:tokio_core::reactor: loop process - 1 events, Duration { secs: 0, nanos: 394853 }
DEBUG:tokio_core::reactor: loop poll - Duration { secs: 0, nanos: 6887 }
DEBUG:tokio_core::reactor: loop time - Instant { tv_sec: 3023957, tv_nsec: 564991670 }
DEBUG:tokio_core::reactor: loop process - 0 events, Duration { secs: 0, nanos: 13533 }
DEBUG:tokio_core::reactor: loop poll - Duration { secs: 0, nanos: 4151989 }
DEBUG:tokio_core::reactor: loop time - Instant { tv_sec: 3023957, tv_nsec: 569162930 }
DEBUG:tokio_core::reactor: notifying a task handle
DEBUG:tokio_core::reactor: loop process - 1 events, Duration { secs: 0, nanos: 73844 }
DEBUG:tokio_core::reactor: loop poll - Duration { secs: 0, nanos: 13053 }
DEBUG:tokio_core::reactor: loop time - Instant { tv_sec: 3023957, tv_nsec: 569270703 }
DEBUG:tokio_core::reactor: scheduling direction for: 0
DEBUG:tokio_core::reactor: blocking
DEBUG:tokio_core::reactor: loop process - 1 events, Duration { secs: 0, nanos: 210769 }
DEBUG:tokio_core::reactor: loop poll - Duration { secs: 0, nanos: 9356 }
DEBUG:tokio_core::reactor: loop time - Instant { tv_sec: 3023957, tv_nsec: 569499347 }
DEBUG:tokio_core::reactor: loop process - 1 events, Duration { secs: 0, nanos: 16918 }
DEBUG:ldap_integrationtests: Create user 51.
DEBUG:tokio_core::reactor: loop poll - Duration { secs: 0, nanos: 9496 }
DEBUG:tokio_core::reactor: loop time - Instant { tv_sec: 3023957, tv_nsec: 569745876 }
DEBUG:tokio_core::reactor: scheduling direction for: 0
DEBUG:tokio_core::reactor: blocking
DEBUG:tokio_core::reactor: scheduling direction for: 0
DEBUG:tokio_core::reactor: blocking
DEBUG:tokio_core::reactor: loop process - 1 events, Duration { secs: 0, nanos: 445253 }
DEBUG:tokio_core::reactor: loop poll - Duration { secs: 0, nanos: 7387 }
DEBUG:tokio_core::reactor: loop time - Instant { tv_sec: 3023957, tv_nsec: 570207555 }
DEBUG:tokio_core::reactor: loop process - 0 events, Duration { secs: 0, nanos: 21457 }
DEBUG:tokio_core::reactor: loop poll - Duration { secs: 0, nanos: 11249323 }
DEBUG:tokio_core::reactor: loop time - Instant { tv_sec: 3023957, tv_nsec: 581483989 }
DEBUG:tokio_core::reactor: notifying a task handle
DEBUG:tokio_core::reactor: loop process - 1 events, Duration { secs: 0, nanos: 70637 }
DEBUG:tokio_core::reactor: loop poll - Duration { secs: 0, nanos: 13203 }
DEBUG:tokio_core::reactor: loop time - Instant { tv_sec: 3023957, tv_nsec: 581575353 }
WARN:ldap3::protocol: discarding frame with unmatched msgid: -128
DEBUG:tokio_core::reactor: scheduling direction for: 0
DEBUG:tokio_core::reactor: blocking
DEBUG:tokio_core::reactor: loop process - 1 events, Duration { secs: 0, nanos: 218536 }
DEBUG:tokio_core::reactor: loop poll - Duration { secs: 0, nanos: 7243 }
DEBUG:tokio_core::reactor: loop time - Instant { tv_sec: 3023957, tv_nsec: 581809719 }
DEBUG:tokio_core::reactor: loop process - 0 events, Duration { secs: 0, nanos: 10890 }

After printing this it just blocks. The test just creates 100 users in a loop, and it always stops at user 51.

sindreij commented 6 years ago

I have added some more debug info in ldap3 and it looks like Active Directory does something funny with the msgid when the id reaches 128

(Note: Looks like it only got to user 27 this time)

EBUG:ldap_integrationtests: Create user 26.
DEBUG:ldap3::protocol: Next ldap id: 127
TRACE:ldap3::protocol: Sending packet: StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 2, payload: P([127]) }, StructureTag { class: Application, id: 8, payload: C([StructureTag { class: Universal, id: 4, payload: P([67, 78, 61, 85, 115, 101, 114, 32, 50, 54, 44, 79, 85, 61, 73, 87, 50, 84, 101, 115, 116, 44, 79, 85, 61, 79, 114, 103, 97, 110, 105, 115, 97, 115, 106, 111, 110, 44, 68, 67, 61, 107, 111, 109, 109, 117, 110, 101, 44, 68, 67, 61, 108, 111, 99, 97, 108]) }, StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 4, payload: P([111, 98, 106, 101, 99, 116, 67, 108, 97, 115, 115]) }, StructureTag { class: Universal, id: 17, payload: C([StructureTag { class: Universal, id: 4, payload: P([116, 111, 112]) }, StructureTag { class: Universal, id: 4, payload: P([112, 101, 114, 115, 111, 110]) }, StructureTag { class: Universal, id: 4, payload: P([117, 115, 101, 114]) }, StructureTag { class: Universal, id: 4, payload: P([111, 114, 103, 97, 110, 105, 122, 97, 116, 105, 111, 110, 97, 108, 80, 101, 114, 115, 111, 110]) }]) }]) }, StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 4, payload: P([99, 110]) }, StructureTag { class: Universal, id: 17, payload: C([StructureTag { class: Universal, id: 4, payload: P([85, 115, 101, 114, 32, 50, 54]) }]) }]) }, StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 4, payload: P([100, 105, 115, 112, 108, 97, 121, 78, 97, 109, 101]) }, StructureTag { class: Universal, id: 17, payload: C([StructureTag { class: Universal, id: 4, payload: P([85, 115, 101, 114, 32, 50, 54]) }]) }]) }, StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 4, payload: P([115, 65, 77, 65, 99, 99, 111, 117, 110, 116, 78, 97, 109, 101]) }, StructureTag { class: Universal, id: 17, payload: C([StructureTag { class: Universal, id: 4, payload: P([116, 101, 115, 116, 95, 117, 115, 101, 114, 95, 50, 54]) }]) }]) }, StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 4, payload: P([117, 115, 101, 114, 80, 114, 105, 110, 99, 105, 112, 97, 108, 78, 97, 109, 101]) }, StructureTag { class: Universal, id: 17, payload: C([StructureTag { class: Universal, id: 4, payload: P([116, 101, 115, 116, 95, 117, 115, 101, 114, 95, 50, 54, 64, 107, 111, 109, 109, 117, 110, 101, 46, 108, 111, 99, 97, 108]) }]) }]) }, StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 4, payload: P([117, 115, 101, 114, 65, 99, 99, 111, 117, 110, 116, 67, 111, 110, 116, 114, 111, 108]) }, StructureTag { class: Universal, id: 17, payload: C([StructureTag { class: Universal, id: 4, payload: P([53, 49, 52]) }]) }]) }]) }]) }]) }
DEBUG:ldap3::protocol: Sending: b"0\x82\x01\x1c\x02\x01\x7fh\x82\x01\x15\x049CN=User\x2026,OU=IW2Test,OU=Organisasjon,DC=kommune,DC=local0\x81\xd708\x04\x0bobjectClass1)\x04\x03top\x04\x06person\x04\x04user\x04\x14organizationalPerson0\x0f\x04\x02cn1\t\x04\x07User\x20260\x18\x04\x0bdisplayName1\t\x04\x07User\x20260\x20\x04\x0esAMAccountName1\x0e\x04\x0ctest_user_2601\x04\x11userPrincipalName1\x1c\x04\x1atest_user_26@kommune.local0\x1b\x04\x12userAccountControl1\x05\x04\x03514"
DEBUG:ldap3::protocol: Received: b"0\x84\0\0\0\x10\x02\x01\x7fi\x84\0\0\0\x07\n\x01\0\x04\0\x04\0"
DEBUG:ldap3::protocol: Tags: [StructureTag { class: Universal, id: 2, payload: P([127]) }]
DEBUG:ldap3::protocol: Msgid: 127
DEBUG:ldap3::protocol: Received: b""
DEBUG:ldap_integrationtests: Create user 27.
DEBUG:ldap3::protocol: Next ldap id: 128
TRACE:ldap3::protocol: Sending packet: StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 2, payload: P([128]) }, StructureTag { class: Application, id: 8, payload: C([StructureTag { class: Universal, id: 4, payload: P([67, 78, 61, 85, 115, 101, 114, 32, 50, 55, 44, 79, 85, 61, 73, 87, 50, 84, 101, 115, 116, 44, 79, 85, 61, 79, 114, 103, 97, 110, 105, 115, 97, 115, 106, 111, 110, 44, 68, 67, 61, 107, 111, 109, 109, 117, 110, 101, 44, 68, 67, 61, 108, 111, 99, 97, 108]) }, StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 4, payload: P([111, 98, 106, 101, 99, 116, 67, 108, 97, 115, 115]) }, StructureTag { class: Universal, id: 17, payload: C([StructureTag { class: Universal, id: 4, payload: P([117, 115, 101, 114]) }, StructureTag { class: Universal, id: 4, payload: P([111, 114, 103, 97, 110, 105, 122, 97, 116, 105, 111, 110, 97, 108, 80, 101, 114, 115, 111, 110]) }, StructureTag { class: Universal, id: 4, payload: P([112, 101, 114, 115, 111, 110]) }, StructureTag { class: Universal, id: 4, payload: P([116, 111, 112]) }]) }]) }, StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 4, payload: P([99, 110]) }, StructureTag { class: Universal, id: 17, payload: C([StructureTag { class: Universal, id: 4, payload: P([85, 115, 101, 114, 32, 50, 55]) }]) }]) }, StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 4, payload: P([100, 105, 115, 112, 108, 97, 121, 78, 97, 109, 101]) }, StructureTag { class: Universal, id: 17, payload: C([StructureTag { class: Universal, id: 4, payload: P([85, 115, 101, 114, 32, 50, 55]) }]) }]) }, StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 4, payload: P([115, 65, 77, 65, 99, 99, 111, 117, 110, 116, 78, 97, 109, 101]) }, StructureTag { class: Universal, id: 17, payload: C([StructureTag { class: Universal, id: 4, payload: P([116, 101, 115, 116, 95, 117, 115, 101, 114, 95, 50, 55]) }]) }]) }, StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 4, payload: P([117, 115, 101, 114, 80, 114, 105, 110, 99, 105, 112, 97, 108, 78, 97, 109, 101]) }, StructureTag { class: Universal, id: 17, payload: C([StructureTag { class: Universal, id: 4, payload: P([116, 101, 115, 116, 95, 117, 115, 101, 114, 95, 50, 55, 64, 107, 111, 109, 109, 117, 110, 101, 46, 108, 111, 99, 97, 108]) }]) }]) }, StructureTag { class: Universal, id: 16, payload: C([StructureTag { class: Universal, id: 4, payload: P([117, 115, 101, 114, 65, 99, 99, 111, 117, 110, 116, 67, 111, 110, 116, 114, 111, 108]) }, StructureTag { class: Universal, id: 17, payload: C([StructureTag { class: Universal, id: 4, payload: P([53, 49, 52]) }]) }]) }]) }]) }]) }
DEBUG:ldap3::protocol: Sending: b"0\x82\x01\x1c\x02\x01\x80h\x82\x01\x15\x049CN=User\x2027,OU=IW2Test,OU=Organisasjon,DC=kommune,DC=local0\x81\xd708\x04\x0bobjectClass1)\x04\x04user\x04\x14organizationalPerson\x04\x06person\x04\x03top0\x0f\x04\x02cn1\t\x04\x07User\x20270\x18\x04\x0bdisplayName1\t\x04\x07User\x20270\x20\x04\x0esAMAccountName1\x0e\x04\x0ctest_user_2701\x04\x11userPrincipalName1\x1c\x04\x1atest_user_27@kommune.local0\x1b\x04\x12userAccountControl1\x05\x04\x03514"
DEBUG:ldap3::protocol: Received: b"0\x84\0\0\0\x13\x02\x04\xff\xff\xff\x80i\x84\0\0\0\x07\n\x01\0\x04\0\x04\0"
DEBUG:ldap3::protocol: Tags: [StructureTag { class: Universal, id: 2, payload: P([255, 255, 255, 128]) }]
DEBUG:ldap3::protocol: Msgid: -128
WARN:ldap3::protocol: discarding frame with unmatched msgid: -128
DEBUG:ldap3::protocol: Received: b""
sindreij commented 6 years ago

Found the bug! When msgid 128 is encoded for the wire as a integer in lber it is encoded as.

02 01 80

Which means a INTEGER with one octet that is 80. And 80 in binary is 10000000, which when read as a 8 bit signed integer is -128.

From my tests it looks like AD reads this as as -128 and when writing back encodes it as a 32 bit signed integer, i.e. ff ff ff 80.

I tried just incrementing count by 1 here: https://github.com/inejge/ldap3/blob/master/lber/src/structures/integer.rs#L31 to always use one more octed than needed, and my tests ran perfect.

I will try to come up with a cleaner solution and create a PR.