[LDAP-Users:406] Re: スクリーンセーバでロックされると、再ログインできない

2009年 1月 15日 (木) 23:54:01 JST

こんばんは、毎度お騒がせしております。

wiresharkで大体の感じがつかめたので、今度は
/var/log/ldap.logのloglevelを(おそらく最強の）4095(dec)にして、
先ほどと同様に

********* ロック状態から　hirasawaで再ログインしようとしているケース
********

をログから観測してみました。
ログは結構でかくなるので、err=49が出ている周りだけを切り取って貼り付けて
おきます。

怪しいのはここら辺かしら？

Jan 15 23:25:50 cent5-30 slapd[6396]: access_allowed: no res from state
(userPassword)
Jan 15 23:25:50 cent5-30 slapd[6396]: => acl_mask: access to entry

類推すると　access_allowedの部分はアクセスはできるが

no res from state(userPassword)の意味がいまいちわかりませんが
no response from state(userPassword)? という意味？

結局ACL周りの問題ではなく、単純に

パスワードそのものが見つからない？といっている？（定かではありませんが)

ご教授いただけると幸いです。

教えてクンでもうしわけありません
平澤

----- ここからログです

Jan 15 23:25:49 cent5-30 slapd[6396]: daemon: read active on 16
Jan 15 23:25:49 cent5-30 slapd[6396]: connection_get(16)
Jan 15 23:25:49 cent5-30 slapd[6396]: connection_get(16): got connid=1
Jan 15 23:25:49 cent5-30 slapd[6396]: connection_read(16): checking for
input on id=1
Jan 15 23:25:49 cent5-30 slapd[6396]: ber_get_next on fd 16 failed
errno=11 (Resource temporarily unavailable)
Jan 15 23:25:49 cent5-30 slapd[6396]: daemon: select: listen=7
active_threads=0 tvp=NULL
Jan 15 23:25:49 cent5-30 slapd[6396]: daemon: select: listen=8
active_threads=0 tvp=NULL
Jan 15 23:25:49 cent5-30 slapd[6396]: do_bind 　　　　　 　　　　　ここ
ら辺からバインド開始？
Jan 15 23:25:50 cent5-30 slapd[6396]: >>> dnPrettyNormal:
<uid=hirasawa,ou=People,dc=hirasawa,dc=private>
Jan 15 23:25:50 cent5-30 slapd[6396]: <<< dnPrettyNormal:
<uid=hirasawa,ou=People,dc=hirasawa,dc=private>,
<uid=hirasawa,ou=people,dc=hirasawa,dc=private>
Jan 15 23:25:50 cent5-30 slapd[6396]: do_bind: version=3
dn="uid=hirasawa,ou=People,dc=hirasawa,dc=private" method=128
Jan 15 23:25:50 cent5-30 slapd[6396]: conn=1 op=2 BIND
dn="uid=hirasawa,ou=People,dc=hirasawa,dc=private" method=128
Jan 15 23:25:50 cent5-30 slapd[6396]: ==> bdb_bind: dn:
uid=hirasawa,ou=People,dc=hirasawa,dc=private
Jan 15 23:25:50 cent5-30 slapd[6396]:
bdb_dn2entry("uid=hirasawa,ou=people,dc=hirasawa,dc=private")
Jan 15 23:25:50 cent5-30 slapd[6396]: => access_allowed: auth access to
"uid=hirasawa,ou=People,dc=hirasawa,dc=private" "userPassword" requested
Jan 15 23:25:50 cent5-30 slapd[6396]: => acl_get: [1] attr userPassword
Jan 15 23:25:50 cent5-30 slapd[6396]: access_allowed: no res from state
(userPassword)
Jan 15 23:25:50 cent5-30 slapd[6396]: => acl_mask: access to entry
"uid=hirasawa,ou=People,dc=hirasawa,dc=private", attr "userPassword"
requested
Jan 15 23:25:50 cent5-30 slapd[6396]: => acl_mask: to value by "", (=0)
Jan 15 23:25:50 cent5-30 slapd[6396]: <= check a_dn_pat: *
Jan 15 23:25:50 cent5-30 slapd[6396]: <= acl_mask: [1] applying
write(=wrscxd) (stop)
Jan 15 23:25:50 cent5-30 slapd[6396]: <= acl_mask: [1] mask: write(=wrscxd)
Jan 15 23:25:50 cent5-30 slapd[6396]: => access_allowed: auth access
granted by write(=wrscxd)
Jan 15 23:25:50 cent5-30 slapd[6396]: send_ldap_result: conn=1 op=2 p=3
Jan 15 23:25:50 cent5-30 slapd[6396]: send_ldap_result: err=49
matched="" text=""
Jan 15 23:25:50 cent5-30 slapd[6396]: send_ldap_response: msgid=3 tag=97
err=49
Jan 15 23:25:50 cent5-30 slapd[6396]: conn=1 op=2 RESULT tag=97 err=49
text=
Jan 15 23:25:50 cent5-30 slapd[6396]: daemon: activity on 1 descriptor
Jan 15 23:25:50 cent5-30 slapd[6396]: daemon: activity on:
Jan 15 23:25:50 cent5-30 slapd[6396]: 16r
Jan 15 23:25:50 cent5-30 slapd[6396]:
Jan 15 23:25:50 cent5-30 slapd[6396]: daemon: read active on 16
Jan 15 23:25:50 cent5-30 slapd[6396]: connection_get(16)
Jan 15 23:25:50 cent5-30 slapd[6396]: connection_get(16): got connid=1
Jan 15 23:25:50 cent5-30 slapd[6396]: connection_read(16): checking for
input on id=1
Jan 15 23:25:50 cent5-30 slapd[6396]: ber_get_next on fd 16 failed
errno=11 (Resource temporarily unavailable)
Jan 15 23:25:50 cent5-30 slapd[6396]: daemon: select: listen=7
active_threads=0 tvp=NULL
Jan 15 23:25:50 cent5-30 slapd[6396]: daemon: select: listen=8
active_threads=0 tvp=NULL
Jan 15 23:25:50 cent5-30 slapd[6396]: do_bind
Jan 15 23:25:50 cent5-30 slapd[6396]: >>> dnPrettyNormal: <>
Jan 15 23:25:51 cent5-30 slapd[6396]: <<< dnPrettyNormal: <>, <>
Jan 15 23:25:51 cent5-30 slapd[6396]: do_bind: version=3 dn="" method=128
Jan 15 23:25:51 cent5-30 slapd[6396]: conn=1 op=3 BIND dn="" method=128
Jan 15 23:25:51 cent5-30 slapd[6396]: send_ldap_result: conn=1 op=3 p=3
Jan 15 23:25:51 cent5-30 slapd[6396]: send_ldap_result: err=0 matched=""
text=""
Jan 15 23:25:51 cent5-30 slapd[6396]: send_ldap_response: msgid=4 tag=97
err=0
Jan 15 23:25:51 cent5-30 slapd[6396]: conn=1 op=3 RESULT tag=97 err=0 text=
Jan 15 23:25:51 cent5-30 slapd[6396]: do_bind: v3 anonymous bind
Jan 15 23:25:53 cent5-30 slapd[6396]: daemon: activity on 1 descriptor
Jan 15 23:25:53 cent5-30 slapd[6396]: daemon: activity on:
Jan 15 23:25:53 cent5-30 slapd[6396]: 16r
Jan 15 23:25:53 cent5-30 slapd[6396]:
Jan 15 23:25:53 cent5-30 slapd[6396]: daemon: read active on 16
Jan 15 23:25:53 cent5-30 slapd[6396]: connection_get(16)
Jan 15 23:25:53 cent5-30 slapd[6396]: connection_get(16): got connid=1
Jan 15 23:25:53 cent5-30 slapd[6396]: connection_read(16): checking for
input on id=1
Jan 15 23:25:53 cent5-30 slapd[6396]: ber_get_next on fd 16 failed
errno=0 (Success)
Jan 15 23:25:53 cent5-30 slapd[6396]: do_unbind
Jan 15 23:25:53 cent5-30 slapd[6396]: connection_read(16): input
error=-2 id=1, closing.
Jan 15 23:25:53 cent5-30 slapd[6396]: conn=1 op=4 UNBIND
Jan 15 23:25:53 cent5-30 slapd[6396]: connection_closing: readying
conn=1 sd=16 for close
Jan 15 23:25:53 cent5-30 slapd[6396]: connection_close: deferring conn=1
sd=16
Jan 15 23:25:53 cent5-30 slapd[6396]: daemon: select: listen=7
active_threads=0 tvp=NULL
Jan 15 23:25:53 cent5-30 slapd[6396]: connection_resched: attempting
closing conn=1 sd=16
Jan 15 23:25:53 cent5-30 slapd[6396]: connection_close: conn=1 sd=16
Jan 15 23:25:53 cent5-30 slapd[6396]: daemon: removing 16
Jan 15 23:25:53 cent5-30 slapd[6396]: conn=1 fd=16 closed
Jan 15 23:25:53 cent5-30 slapd[6396]: daemon: select: listen=8
active_threads=0 tvp=NULL
Jan 15 23:25:53 cent5-30 slapd[6396]: daemon: activity on 2 descriptors
Jan 15 23:25:54 cent5-30 slapd[6396]: daemon: activity on:

toshi hirasawa さんは書きました:
> こんにちは、菊池さま
>
> いろいろと丁寧にご教授いただき
> ありがとうございます。
>
> 最初にひとつ訂正されていただきます。
> クライアントでの/var/log/messagをみてみたところ
> gnome-screensaver-dialog: pam_ldap: error tring to bind as u ser
> "dn=hirasawa,ou=People,
> dc=hirasawa,dc=private" (Invalid credentials)
> がでてました。
> （サーバの方をみて、無いとかおもってましたよ、あほですね　> 自分）
>
>
> なにが流れているをみるため、wiresharkを使ってパケットを調べてみました。
> LDAPのパケットのやり取りのシーケンスがわかっていないため、
> それぞれ、サーバとクライアントでなにをやっているのか？なのですが、
> こんな感じです。
>
> ********* ロック状態から　hirasawaで再ログインしようとしているケース
> ********
>
> 左がクライアント　、右がサーバです。
>
>   
>>> の矢印が　左から右への流れ
>>>       
> 　<< の矢印が　右から左への流れです。
>
> --------- ここから --------------------------------------------
> 　　>> BindRequest(1) "<root>" simple
> << BindRequest(1) success
>
>   
>>> SearchRequest(2) "dc=hirasawa,dc=private" wholeSubtree
>>>       
> << SerachResEntry(2) "uid=hirasawa,ou=People,dc=hirasawa,dc=private"
> << SerachResEntry(2) success [1 result]
>
>   
>>> SearchRequest(3) "dc=hirasawa,dc=private" wholeSubtree
>>>       
> << SerachResEntry(3) "uid=hirasawa,ou=People,dc=hirasawa,dc=private"
> << SerachResEntry(3) success [1 result]
>
>
>   
>>> BindRequest(1) "<root>" simple
>>>       
> << BindRequest(1) success
>
>   
>>> SearchRequest(2) "dc=hirasawa,dc=private" wholeSubtree
>>>       
> << SerachResEntry(2) "uid=hirasawa,ou=People,dc=hirasawa,dc=private"
> << SerachResEntry(2) success [1 result]
>
>   
>>> BindRequest(3) "uid=hirasawa,ou=People,dc=hirasawa,dc=private" simple
>>>       
> << BindRequest(3) invalidCredentials
>
>   
>>> BindRequest(4) "<root> " simple
>>>       
> << BindRequest(4) success
>
>   
>>> UnbindReqest(5)
>>>       
>
>   
>>> SearchRequest(4) "dc=hirasawa,dc=private" WholeSubtree
>>>       
> << SerachResEntry(4) "uid=hirasawa,ou=People,dc=hirasawa,dc=private"
> << SerachResEntry(4) success [1 result]
>
>
> と、LDAPの部分だけ抜き出してかいてみました。
>
> 菊池さんのおっしゃるように　<root>ではなく　hirasawa権限でbindしようとして
> けられている(invalidCredentials)のようで、
>
> 自分なりに解釈すると
>
> ldapsearch -x -D "cn=Manager,dc=hirasawa,dc=private"はOKだけど
>
> ldapserch -x -D "uid=hirasawa,ou=People,dc=hiraawa,dc=pviate"は許しません
>
> ってことでしょうか？
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
> 　
> Kenji Kikuchi さんは書きました:
>   
>> 平澤 さん
>>
>>
>> こんにちは、菊池です。
>>
>>   
>>     
>>> ここでおっしゃっているパスワードとはどの(だれの）バスワード
>>> になるのでしょうか？
>>>     
>>>       
>> 先のメールで拝見したログには、以下の出力がありました。
>>   
>>     
>>>> Jan 14 19:14:50 cent5-30 slapd[5478]: conn=7 op=2 BIND
>>>> ★dn="uid=hirasawa,ou=People,dc=hirasawa,dc=private"★ method=128
>>>> Jan 14 19:14:50 cent5-30 slapd[5478]: conn=7 op=2 RESULT tag=97 err=49
>>>> text=
>>>>       
>>>>         
>> これより、
>> BIND(認証)処理は、以下のユーザ(DN)に対して行われていることがわかります。
>>    "uid=hirasawa,ou=People,dc=hirasawa,dc=private"
>>
>> ですので、OpenLDAPサーバに登録したエントリ
>>    "uid=hirasawa,ou=People,dc=hirasawa,dc=private"
>> のuserPassword属性として保存している{MD5}形式の値、
>> ([LDAP-Users:390]の内容からは)
>> ----------------------------------------
>>   
>>     
>>> [root ＠ cent5-8 ~]# ldapsearch -x -c -D
>>> "cn=Manager,dc=hirasawa,dc=private" -W -b "dc=hirasawa,dc=private"
>>> "uid=hirasawa"
>>> Enter LDAP Password:
>>> # extended LDIF
>>>     
>>>       
>> ...[略]...
>>   
>>     
>>> # hirasawa, People, hirasawa.private
>>> dn: uid=hirasawa,ou=People,dc=hirasawa,dc=private
>>>     
>>>       
>> ...[略]...
>>   
>>     
>>> userPassword:: e21kNX0kMSRvQ1l5Tk9yayRWRUgzNlhRQWw2dDBua1pkR0hDcGwu
>>>     
>>>       
>> ----------------------------------------
>> # echo -n "e21kNX0kMSRvQ1l5Tk9yayRWRUgzNlhRQWw2dDBua1pkR0hDcGwu" | base64 -d ; echo
>> {md5}$1$oCYyNOrk$VEH36XQAl6t0nkZdGHCpl.
>>
>> と、スクリーンセーバ解除時にタイプしOpenLDAPサーバに送付されている値が
>> {MD5}形式に変換された後に、同じであるかを確認する必要があるかと思います。
>>
>>
>>   
>>     
>>> /var/log/messageにはldapがらみのログはなんも
>>>     
>>>       
>> 私の環境で、スクリーンセーバのパスワードを間違うと、/var/log/messages は、
>> 以下のような出力があるので、確認してみました。
>> -------------------
>> [Date Time] [Host name] gnome-screensaver-dialog: pam_ldap: error trying to bind as user [DN ...例えば"uid=hirasawa,ou=People,dc=hirasawa,dc=private"] (Invalid credentials)
>> -------------------
>>
>>
>> 今回はできたー、今回はできないーと、結果が不規則なこともあり入力を疑いました。
>>
>>
>> toshi hirasawa wrote:
>>   
>>     
>>> こんばんは、
>>> 菊池さん、ご返答ありがとうございます。
>>>
>>> 確かにgnome-screensaverの再ログインでは
>>> err=49が
>>> 毎回でていいますね。
>>>
>>>     
>>>       
>>>> ユーザ名を利用した認証になると、err=49 とNGですので、
>>>> パスワードが違うのではないでしょうか。
>>>>       
>>>>         
>>> ここでおっしゃっているパスワードとはどの(だれの）バスワード
>>> になるのでしょうか？
>>>
>>>     
>>>       
>>>> この他、/var/log/messagesには、gnome-screensaver-dialogも
>>>> 認証(bind)に失敗したことを認識している旨のメッセージがないでしょうか。
>>>>       
>>>>         
>>> /var/log/messageにはldapがらみのログはなんも
>>>
>>>
>>>
>>>     
>>>       
>
>
>   