[jcifs] NTLM usrname/password failure after each 5 mins
AsafM
asaf.mesika at gmail.com
Sun Jun 15 21:07:09 GMT 2008
Hi all,
I'm reviving a 2 years old topic, regarding load testing.
You can take a look at the entire thread of the discussion
http://www.nabble.com/NTLM-usrname-password-failure-after-each-5-mins-td5381546.html#a5391633
here
I'll start with a quick summary, and then shed lots of details to make it
clearer:
After the transport disconnects (due to socket timeout) and connects, the
first 10 , or so, attempts to authenticate against the DC fails on bad
username/password. After those failures, all attempts succeeds.
I've gained some knowledge I'll now share, but I'm still missing some key
elements to figuring this out.
Load Testing Setup
110 threads, consistently accessing a protected resource on Tomcat, which
requires an NTLM authentication.
Each thread is using one user. For example: Thread-34 is logging in as user
TEST34.
The turn of events
1. The first thread accessing the resource, setups the session
(SmbSession.sessionSetup()), which blocks all other threads, since each
thread (user) requires to setup a session of its own.
The session setup runs the Transport.connect(), creates a tree for the
default user (to enable SMB signing), and send the SmbComSessionSetupAndX to
the DC, for authentication.
2. Once the 1st session setup is done, all other threads follows, each
creating its own session, attached to one transport object (Transport-1
thread).
3. On the second iteration of the test threads, there's no need for session
setup. The session object is retrieved from the transport (it's cached
there).
This usage of cache causes the lack of usage in the transport socket.
4. After soTimeout (jcifs constant of 5 min), the loop() method of Transport
receives a SocketTimeoutException, and calls Transport.disconnect() which in
turn calls SmbTransport.doDisconnect().
5. The doDisconnect() logs off all sessions attached to the transport
object, closes down the socket and finally resets the digest property, which
is used to sign each request sent to the DC (this is set in the first
sessionSetup in SmbSession).
** First Problem**
While disconnects logs-off sessions, other threads were using them, and
acting as-if the transport is connected.
I've bypassed this issue, by:
a) Setting the Transport.state to 0 in the Transport.disconnect() function.
This causes the Transport.connect() to actually connect.
b) Adding a synchronize (this) block on both disconnect() and connect()
methods, which prevents running connect() while disconnect() is commencing.
6. While disconnect() was running, all other threads were waiting in queue,
to run transport.connect(), in the SmbTree.treeConnect() method.
Once the disconnect finished, each thread in its turn, ran the connect
and cotinued for creating a session by running SmbSession.sessionSetup().
Since that function is syncrhonized on transport(), sessions were created
once at a time, for each thread.
7. The first session to run the setup, identified that the transport.digest
was empty (due to SmbTransport.doDisconnect()), thus ran treeConnect on the
default username, used for SMB signing.
Once that was finished successfully, it sent the SmbComSessionSetupAndX for
the user it was trying to authenticate.
It failed in the DC. SmbComSessionSetupAndXResponse returned with an error
code: Logon failure: unknown user name or bad password
8. Allot of threads after the first thread inline, failed also on the exact
spot in the sessionSetup().
9. From some magical reason, which I'm yet to figure out, after 10 or so
failures, the DC started returning success in the
SmbComSessionSetupAndXResponse.
Log File
Here's the log file. Please ignore some lines that are not related jCIFS.
They are part of our tested web application.
This is after the socket timeout occurs:
2008-06-12 16:00:37,702 373674 ERROR [STDERR] (Transport1:)
SmbComTreeDisconnect[command=SMB_COM_TREE_DISCONNECT,received=false,errorCode=0,flags=0x0018,flags2=0xC007,signSeq=220,tid=2061,pid=2761,uid=2061,mid=0,wordCount=0,byteCount=0]
2008-06-12 16:00:37,717 373689 ERROR [STDERR] (Transport1:)
SmbComLogoffAndX[command=SMB_COM_LOGOFF_ANDX,received=false,errorCode=0,flags=0x0018,flags2=0xC007,signSeq=222,tid=0,pid=2761,uid=2061,mid=0,wordCount=2,byteCount=0,andxCommand=0xFF,andxOffset=0]
2008-06-12 16:00:37,717 373689 ERROR [STDERR] (Transport1:)
SmbComTreeDisconnect[command=SMB_COM_TREE_DISCONNECT,received=false,errorCode=0,flags=0x0018,flags2=0xC007,signSeq=224,tid=2062,pid=2761,uid=2062,mid=0,wordCount=0,byteCount=0]
2008-06-12 16:00:38,874 374846 ERROR [STDERR] (Transport1:)
SmbComNegotiate[command=SMB_COM_NEGOTIATE,received=false,errorCode=0,flags=0x0018,flags2=0xC003,signSeq=0,tid=0,pid=2761,uid=0,mid=112,wordCount=0,byteCount=12,wordCount=0,dialects=NT
LM 0.12]
2008-06-12 16:00:38,874 374846 ERROR [STDERR] (Transport1:) New data read:
Transport1[KDC-DEV<00>/192.168.1.200:0]
2008-06-12 16:00:38,874 374846 ERROR [STDERR] (Transport1:) 00000: FF 53 4D
42 72 00 00 00 00 98 03 C0 00 00 00 00 |ÿSMBr......À....|
00010: 00 00 00 00 00 00 00 00 00 00 C9 0A 00 00 70 00 |..........É...p.|
2008-06-12 16:00:38,889 374861 ERROR [STDERR] (Transport1:)
SmbComNegotiateResponse[command=SMB_COM_NEGOTIATE,received=false,errorCode=0,flags=0x0098,flags2=0xC003,signSeq=0,tid=0,pid=2761,uid=0,mid=112,wordCount=17,byteCount=36,wordCount=17,dialectIndex=0,securityMode=0xF,security=user,encryptedPasswords=true,maxMpxCount=50,maxNumberVcs=1,maxBufferSize=16644,maxRawSize=65536,sessionKey=0x00000000,capabilities=0x0001F3FD,serverTime=Thu
Jun 12 16:03:40 IDT
2008,serverTimeZone=240,encryptionKeyLength=8,byteCount=36,encryptionKey=0xC085385D850EA2B7,oemDomainName=ZONE2]
2008-06-12 16:00:38,905 374877 ERROR [STDERR] (http-0.0.0.0-8080-30:)
treeConnect: unc=\\KDC-DEV\IPC$,service=IPC
2008-06-12 16:00:38,905 374877 ERROR [STDERR] (http-0.0.0.0-8080-30:)
sessionSetup: accountName=TEST92,primaryDomain=ZONE2, digest = null
2008-06-12 16:00:38,905 374877 INFO [com.srndpt.serving.ServingServlet]
(http-0.0.0.0-8080-3:) Feed 'LoadTest' served to user TEST7 in 360 ms.
2008-06-12 16:00:38,920 374892 INFO
[com.srndpt.core.authentication.bean.NTLMLoginModule]
(http-0.0.0.0-8080-30:) Domain controller refused access to TEST92
2008-06-12 16:00:38,952 374924 INFO
[com.srndpt.core.authentication.bean.NTLMLoginModule]
(http-0.0.0.0-8080-21:) Starting NTLM login...
2008-06-12 16:00:38,967 374939 INFO
[com.srndpt.core.authentication.bean.NTLMLoginModule]
(http-0.0.0.0-8080-21:) NTLM credentials obtained
2008-06-12 16:00:38,967 374939 ERROR [STDERR] (http-0.0.0.0-8080-21:)
treeConnect: unc=\\KDC-DEV\IPC$,service=IPC
2008-06-12 16:00:38,983 374955 ERROR [STDERR] (http-0.0.0.0-8080-21:)
sessionSetup: accountName=TEST55,primaryDomain=ZONE2, digest = null
2008-06-12 16:00:38,983 374955 ERROR [STDERR] (http-0.0.0.0-8080-21:)
sessionSetup: Finished created request and response
2008-06-12 16:00:38,983 374955 ERROR [STDERR] (http-0.0.0.0-8080-21:)
isSignatureSetupRequired: flags2=true, authFlag=true, passFlag=true,
digestNull=true
2008-06-12 16:00:38,999 374971 ERROR [STDERR] (http-0.0.0.0-8080-21:)
Signature setup is required for ZONE2\TEST55 and is now performed...
2008-06-12 16:00:38,999 374971 ERROR [STDERR] (http-0.0.0.0-8080-21:)
treeConnect: unc=\\KDC-DEV\IPC$,service=IPC
2008-06-12 16:00:38,999 374971 ERROR [STDERR] (http-0.0.0.0-8080-21:)
sessionSetup: accountName=worklight,primaryDomain=ZONE2.DEVNET.LOCAL, digest
= null
2008-06-12 16:00:38,999 374971 ERROR [STDERR] (http-0.0.0.0-8080-21:)
sessionSetup: Finished created request and response
2008-06-12 16:00:38,999 374971 ERROR [STDERR] (http-0.0.0.0-8080-21:)
isSignatureSetupRequired: flags2=true, authFlag=true, passFlag=true,
digestNull=true
2008-06-12 16:00:38,999 374971 ERROR [STDERR] (http-0.0.0.0-8080-21:)
Signature setup is required for ZONE2.DEVNET.LOCAL\worklight, but hash is
NOT external
2008-06-12 16:00:39,014 374986 ERROR [STDERR] (http-0.0.0.0-8080-21:)
SmbComSessionSetupAndX[command=SMB_COM_SESSION_SETUP_ANDX,received=false,errorCode=0,flags=0x0018,flags2=0xC007,signSeq=0,tid=0,pid=2761,uid=0,mid=113,wordCount=13,byteCount=141,andxCommand=0x75,andxOffset=202,snd_buf_size=16644,maxMpxCount=10,VC_NUMBER=1,sessionKey=0,passwordLength=24,unicodePasswordLength=24,capabilities=4180,accountName=worklight,primaryDomain=ZONE2.DEVNET.LOCAL,NATIVE_OS=Windows
XP,NATIVE_LANMAN=jCIFS]
2008-06-12 16:00:39,014 374986 ERROR [STDERR] (http-0.0.0.0-8080-21:)
SmbComTreeConnectAndX[command=SMB_COM_TREE_CONNECT_ANDX,received=false,errorCode=0,flags=0x0018,flags2=0x0000,signSeq=0,tid=0,pid=2761,uid=0,mid=0,wordCount=4,byteCount=35,andxCommand=0xFF,andxOffset=0,disconnectTid=false,passwordLength=1,password=,path=\\KDC-DEV\IPC$,service=IPC]
2008-06-12 16:00:39,014 374986 ERROR [STDERR] (Transport1:) New data read:
Transport1[KDC-DEV<00>/192.168.1.200:0]
2008-06-12 16:00:39,014 374986 ERROR [STDERR] (Transport1:) 00000: FF 53 4D
42 73 00 00 00 00 98 07 C0 00 00 7B C3 |ÿSMBs......À..{Ã|
00010: 96 9F 9B C8 1C 11 00 00 01 18 C9 0A 03 20 71 00 |...È......É.. q.|
2008-06-12 16:00:39,030 375002 ERROR [STDERR] (Transport1:)
SmbComSessionSetupAndXResponse[command=SMB_COM_SESSION_SETUP_ANDX,received=false,errorCode=0,flags=0x0098,flags2=0xC007,signSeq=1,tid=6145,pid=2761,uid=8195,mid=113,wordCount=3,byteCount=152,andxCommand=0x75,andxOffset=193,isLoggedInAsGuest=false,nativeOs=Windows
Server 2003 R2 3790 Service Pack 1,nativeLanMan=Windows Server 2003 R2
5.2,primaryDomain=ZONE2]
2008-06-12 16:00:39,030 375002 ERROR [STDERR] (http-0.0.0.0-8080-21:)
SmbComSessionSetupAndX[command=SMB_COM_SESSION_SETUP_ANDX,received=false,errorCode=0,flags=0x0018,flags2=0xC007,signSeq=2,tid=0,pid=2761,uid=0,mid=114,wordCount=13,byteCount=85,andxCommand=0x75,andxOffset=146,snd_buf_size=16644,maxMpxCount=10,VC_NUMBER=1,sessionKey=0,passwordLength=24,unicodePasswordLength=0,capabilities=4180,accountName=TEST55,primaryDomain=ZONE2,NATIVE_OS=Windows
XP,NATIVE_LANMAN=jCIFS]
2008-06-12 16:00:39,045 375017 ERROR [STDERR] (http-0.0.0.0-8080-21:)
SmbComTreeConnectAndX[command=SMB_COM_TREE_CONNECT_ANDX,received=false,errorCode=0,flags=0x0018,flags2=0x0000,signSeq=0,tid=0,pid=2761,uid=0,mid=0,wordCount=4,byteCount=35,andxCommand=0xFF,andxOffset=0,disconnectTid=false,passwordLength=1,password=,path=\\KDC-DEV\IPC$,service=IPC]
2008-06-12 16:00:39,045 375017 INFO [com.srndpt.serving.ServingServlet]
(http-0.0.0.0-8080-1:) Feed 'LoadTest' served to user TEST53 in 500 ms.
2008-06-12 16:00:39,092 375064 ERROR [STDERR] (Transport1:) New data read:
Transport1[KDC-DEV<00>/192.168.1.200:0]
2008-06-12 16:00:39,108 375080 ERROR [STDERR] (Transport1:) 00000: FF 53 4D
42 73 6D 00 00 C0 98 07 C0 00 00 0A F3 |ÿSMBsm..À..À...ó|
00010: A8 F6 6F 1C C4 EF 00 00 00 00 C9 0A 00 00 72 00 |¨öo.Äï....É...r.|
2008-06-12 16:00:39,108 375080 ERROR [STDERR] (Transport1:)
SmbComSessionSetupAndXResponse[command=SMB_COM_SESSION_SETUP_ANDX,received=false,errorCode=Logon
failure: unknown user name or bad
password.,flags=0x0098,flags2=0xC007,signSeq=3,tid=0,pid=2761,uid=0,mid=114,wordCount=0,byteCount=0,andxCommand=0xFF,andxOffset=0,isLoggedInAsGuest=false,nativeOs=,nativeLanMan=,primaryDomain=]
2008-06-12 16:00:39,108 375080 INFO [com.srndpt.serving.ServingServlet]
(http-0.0.0.0-8080-16:) Feed 'LoadTest' served to user TEST108 in 547 ms.
2008-06-12 16:00:39,139 375111 ERROR
[com.srndpt.core.authentication.bean.NTLMLoginModule]
(http-0.0.0.0-8080-21:) NTLM Authentication error while trying to login
jcifs.smb.SmbAuthException: Logon failure: unknown user name or bad
password.
at jcifs.smb.SmbTransport.checkStatus(SmbTransport.java:521)
at jcifs.smb.SmbTransport.send(SmbTransport.java:633)
at jcifs.smb.SmbSession.sessionSetup(SmbSession.java:285)
at jcifs.smb.SmbSession.send(SmbSession.java:233)
at jcifs.smb.SmbTree.treeConnect(SmbTree.java:154)
at jcifs.smb.SmbSession.logon(SmbSession.java:169)
at jcifs.smb.SmbSession.logon(SmbSession.java:162)
at
com.srndpt.core.authentication.bean.NTLMLoginModule.login(NTLMLoginModule.java:162)
at sun.reflect.GeneratedMethodAccessor141.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at javax.security.auth.login.LoginContext.invoke(LoginContext.java:769)
at javax.security.auth.login.LoginContext.access$000(LoginContext.java:186)
at javax.security.auth.login.LoginContext$4.run(LoginContext.java:683)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.login.LoginContext.invokePriv(LoginContext.java:680)
at javax.security.auth.login.LoginContext.login(LoginContext.java:579)
at
org.jboss.security.plugins.JaasSecurityManager.defaultLogin(JaasSecurityManager.java:601)
at
org.jboss.security.plugins.JaasSecurityManager.authenticate(JaasSecurityManager.java:535)
at
org.jboss.security.plugins.JaasSecurityManager.isValid(JaasSecurityManager.java:344)
at
Thanks alot of taking the time to read all of this!
Asaf Mesika
Michael B Allen-4 wrote:
>
> Alexandr,
>
> Honestly I can't look into this much. I'm busy trying to start a company
> (that has nothing to do with jcifs BTW). I can answer emails but I'm
> afraid the only way you'll really get to the bottom of the problem is to
> look at the jCIFS source and figure out how it works for yourself. That's
> the nature of Open Source sometimes.
>
> As for what I think is happening, I don't know. My understanding of the
> code was that a transport would only close if the connection was idle. So
> if you are using a fixed number of credentials that are all initialized
> on startup and there is no further communication with the DC then the
> transport closing is normal and we're back to the original response which
> is that it's a problem inherent to the NTLM multistep handshake. Note
> however that it will likely not occur in production because the chances
> of someone logging in at the exact moment the transport closes are slim
> (with a sufficiently high soTImeout).
>
> Mike
>
> On Fri, 21 Jul 2006 10:11:44 +0400
> "Alexandr Podoplelov" <alepod at gmail.com> wrote:
>
>> Yes, it's a stress test and I do use different credentials. The problem
>> occured after the first read timeout. Can it be possible to increase the
>> timeout value. I use jcifs of version 1.2.9 . Maybe it makes sence to add
>> some extra log prints into sources?
>>
>> //Alexander
>>
>> 2006/7/20, Michael B Allen <mba2000 at ioplex.com>:
>> >
>> > Actually I forgot you're stess testing. Are you using different
>> > credentials? That would explain the different sessions.
>> > --
>> > Michael B Allen
>> > PHP Extension for SSO w/ Windows Group Authorization
>> > http://www.ioplex.com/
>> >
>>
>
>
> --
> Michael B Allen
> PHP Extension for SSO w/ Windows Group Authorization
> http://www.ioplex.com/
>
>
--
View this message in context: http://www.nabble.com/NTLM-usrname-password-failure-after-each-5-mins-tp5381546p17805529.html
Sent from the Samba - jcifs mailing list archive at Nabble.com.
More information about the jcifs
mailing list