Bug 33717

Summary:	Не включаются логи в /etc/krb5.conf
Product:	Sisyphus	Reporter:	Vitaly Lipatov <lav>
Component:	libkrb5	Assignee:	Evgeny Sinelnikov <sin>
Status:	NEW ---	QA Contact:	qa-sisyphus
Severity:	normal
Priority:	P3	CC:	cas, iv, shaba, sin
Version:	unstable
Hardware:	all
OS:	Linux

Description Vitaly Lipatov 2017-08-02 03:17:46 MSK

В начале /etc/krb5.conf есть записи о логах
[logging]
# default = FILE:/var/log/krb5libs.log
# kdc = FILE:/var/log/krb5kdc.log
# admin_server = FILE:/var/log/kadmind.log

даже если строки раскомментировать, и указать другие пути, куда точно есть все права, никакие файлы с логами не пишутся, что затрудняет отладку.

Comment 1 Evgeny Sinelnikov 2017-10-26 13:02:50 MSK

Не понятно как должны работать эти логи и что ожидается, когда делается вывод, что логи не включаются. Эти логи имеют отношение, скорее всего, исключительно к серверу. Клиентские логи так включить не получиться.

Comment 2 Vitaly Lipatov 2017-10-26 13:38:24 MSK

(В ответ на комментарий №1)
> Не понятно как должны работать эти логи и что ожидается, когда делается вывод,
> что логи не включаются. Эти логи имеют отношение, скорее всего, исключительно к
> серверу. Клиентские логи так включить не получиться.
Я бы хотел на клиенте получить какие-то логи обращения к krb.
Строка krb5libs в
default = FILE:/var/log/krb5libs.log
наводит на мысль, что есть логи библиотек.

Существуют ли вообще клиентские логи?
И зачем в конфиге на клиенте серверные настройки?

Comment 3 Evgeny Sinelnikov 2017-10-26 13:55:07 MSK

Обеспечить логирование на клиенте - это задача клиента. Библиотека не может делать общий лог в заданное общее место под разными пользователями, да ещё и неявно.

Тем не менее сервер - тоже сам себе клиент. Не "на клиенте серверные настройки", а "на сервере - клиентские". Так что это общий конфиг.

Тем не менее отладку на клиенте включить можно:
https://web.mit.edu/kerberos/krb5-1.14/doc/admin/troubleshoot.html

Под Сентосью:

[sin@centos ~]$ kvno krbtgt/DARKMASTERSIN.NET
krbtgt/DARKMASTERSIN.NET@DARKMASTERSIN.NET: kvno = 1

[sin@centos ~]$ env KRB5_TRACE=/dev/stdout kvno krbtgt/DARKMASTERSIN.NET
[21749] 1509014972.185713: Getting credentials sin@DARKMASTERSIN.NET -> krbtgt/DARKMASTERSIN.NET@DARKMASTERSIN.NET using ccache KEYRING:persistent:1000:1000
[21749] 1509014972.186517: Retrieving sin@DARKMASTERSIN.NET -> krbtgt/DARKMASTERSIN.NET@DARKMASTERSIN.NET from KEYRING:persistent:1000:1000 with result: 0/Success
krbtgt/DARKMASTERSIN.NET@DARKMASTERSIN.NET: kvno = 1

[sin@centos ~]$ env KRB5_TRACE=/dev/stdout kinit
[21751] 1509014993.721273: Getting initial credentials for sin@DARKMASTERSIN.NET
[21751] 1509014993.722042: Sending request (194 bytes) to DARKMASTERSIN.NET
[21751] 1509014993.790102: Resolving hostname kerberos.darkmastersin.net.
[21751] 1509014993.835574: Sending initial UDP request to dgram 2a02:2698:7023:eda8::36:88
[21751] 1509014994.836949: Sending initial UDP request to dgram 109.195.19.40:88
[21751] 1509014995.838758: Resolving hostname kerberos.darkmastersin.net.
[21751] 1509014995.882475: Initiating TCP connection to stream 2a02:2698:7023:eda8::36:88
[21751] 1509014996.883796: Initiating TCP connection to stream 109.195.19.40:88
[21751] 1509014996.942205: Sending TCP request to stream 109.195.19.40:88
[21751] 1509014997.7477: Received answer (274 bytes) from stream 109.195.19.40:88
[21751] 1509014997.7534: Terminating TCP connection to stream 2a02:2698:7023:eda8::36:88
[21751] 1509014997.7554: Terminating TCP connection to stream 109.195.19.40:88
[21751] 1509014997.44984: Response was from master KDC
[21751] 1509014997.45110: Received error from KDC: -1765328359/Additional pre-authentication required
[21751] 1509014997.45201: Processing preauth types: 136, 19, 2, 133
[21751] 1509014997.45224: Selected etype info: etype rc4-hmac, salt "DARKMASTERSIN.NETsin", params ""
[21751] 1509014997.45232: Received cookie: MIT
Password for sin@DARKMASTERSIN.NET: 
[21751] 1509015004.185824: AS key obtained for encrypted timestamp: rc4-hmac/2962
[21751] 1509015004.186004: Encrypted timestamp (for 1509015014.723487): plain 301AA011180F32303137313032363130353031345AA10502030B0A1F, encrypted 3004BE7224752AC766C76FFCBB84D624171D534474697586E052FDA37241889B90DEE7E2CF4330F360E88E924757EA43CBDF2710
[21751] 1509015004.186127: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
[21751] 1509015004.186141: Produced preauth for next request: 133, 2
[21751] 1509015004.186203: Sending request (285 bytes) to DARKMASTERSIN.NET
[21751] 1509015004.255012: Resolving hostname kerberos.darkmastersin.net.
[21751] 1509015004.264206: Sending initial UDP request to dgram 2a02:2698:7023:eda8::36:88
[21751] 1509015005.265484: Sending initial UDP request to dgram 109.195.19.40:88
[21751] 1509015006.266748: Resolving hostname kerberos.darkmastersin.net.
[21751] 1509015006.311215: Initiating TCP connection to stream 2a02:2698:7023:eda8::36:88
[21751] 1509015007.312691: Initiating TCP connection to stream 109.195.19.40:88
[21751] 1509015007.370416: Sending TCP request to stream 109.195.19.40:88
[21751] 1509015007.526729: Received answer (727 bytes) from stream 109.195.19.40:88
[21751] 1509015007.526793: Terminating TCP connection to stream 2a02:2698:7023:eda8::36:88
[21751] 1509015007.526814: Terminating TCP connection to stream 109.195.19.40:88
[21751] 1509015007.559651: Response was from master KDC
[21751] 1509015007.559736: Processing preauth types: 19
[21751] 1509015007.559750: Selected etype info: etype rc4-hmac, salt "DARKMASTERSIN.NETsin", params ""
[21751] 1509015007.559762: Produced preauth for next request: (empty)
[21751] 1509015007.559775: AS key determined by preauth: rc4-hmac/2962
[21751] 1509015007.559834: Decrypted AS reply; session key is: des3-cbc-sha1/38DA
[21751] 1509015007.561839: FAST negotiation: available
[21751] 1509015007.561897: Initializing KEYRING:persistent:1000:1000 with default princ sin@DARKMASTERSIN.NET
[21751] 1509015007.562023: Storing sin@DARKMASTERSIN.NET -> krbtgt/DARKMASTERSIN.NET@DARKMASTERSIN.NET in KEYRING:persistent:1000:1000
[21751] 1509015007.562094: Storing config in KEYRING:persistent:1000:1000 for krbtgt/DARKMASTERSIN.NET@DARKMASTERSIN.NET: fast_avail: yes
[21751] 1509015007.562114: Storing sin@DARKMASTERSIN.NET -> krb5_ccache_conf_data/fast_avail/krbtgt\/DARKMASTERSIN.NET\@DARKMASTERSIN.NET@X-CACHECONF: in KEYRING:persistent:1000:1000
[21751] 1509015007.562159: Storing config in KEYRING:persistent:1000:1000 for krbtgt/DARKMASTERSIN.NET@DARKMASTERSIN.NET: pa_type: 2
[21751] 1509015007.562172: Storing sin@DARKMASTERSIN.NET -> krb5_ccache_conf_data/pa_type/krbtgt\/DARKMASTERSIN.NET\@DARKMASTERSIN.NET@X-CACHECONF: in KEYRING:persistent:1000:1000

На Альтах:

[sin@base ~]$ env KRB5_TRACE=/dev/stdout kvno krbtgt/DARKMASTERSIN.NET
[12493] 1509014989.631490: Getting credentials sin@DARKMASTERSIN.NET -> krbtgt/DARKMASTERSIN.NET@DARKMASTERSIN.NET using ccache KEYRING:persistent:500:500
[12493] 1509014989.631677: Retrieving sin@DARKMASTERSIN.NET -> krbtgt/DARKMASTERSIN.NET@DARKMASTERSIN.NET from KEYRING:persistent:500:500 with result: 0/Success
krbtgt/DARKMASTERSIN.NET@DARKMASTERSIN.NET: kvno = 1

[sin@base ~]$ env KRB5_TRACE=/dev/stdout kinit
[12496] 1509015001.883520: Getting initial credentials for sin@DARKMASTERSIN.NET
[12496] 1509015001.890099: Sending request (194 bytes) to DARKMASTERSIN.NET
[12496] 1509015001.892629: Resolving hostname kerberos.darkmastersin.net.
[12496] 1509015001.894107: Sending initial UDP request to dgram 2a02:2698:7023:eda8::36:88
[12496] 1509015002.894514: Sending initial UDP request to dgram 109.195.19.40:88
[12496] 1509015003.895823: Resolving hostname kerberos.darkmastersin.net.
[12496] 1509015003.897169: Initiating TCP connection to stream 2a02:2698:7023:eda8::36:88
[12496] 1509015004.898452: Initiating TCP connection to stream 109.195.19.40:88
[12496] 1509015004.900319: Sending TCP request to stream 109.195.19.40:88
[12496] 1509015004.902807: Received answer (274 bytes) from stream 109.195.19.40:88
[12496] 1509015004.902886: Terminating TCP connection to stream 2a02:2698:7023:eda8::36:88
[12496] 1509015004.902929: Terminating TCP connection to stream 109.195.19.40:88
[12496] 1509015004.904497: Response was from master KDC
[12496] 1509015004.904701: Received error from KDC: -1765328359/Additional pre-authentication required
[12496] 1509015004.904814: Processing preauth types: 136, 19, 2, 133
[12496] 1509015004.904848: Selected etype info: etype rc4-hmac, salt "DARKMASTERSIN.NETsin", params ""
[12496] 1509015004.904861: Received cookie: MIT
Password for sin@DARKMASTERSIN.NET: 
[12496] 1509015009.975544: AS key obtained for encrypted timestamp: rc4-hmac/2962
[12496] 1509015009.975703: Encrypted timestamp (for 1509015229.327514): plain 301AA011180F32303137313032363130353334395AA105020304FF5A, encrypted D7CD55AE6D6AF0B66E89AFEB64371085DCA95942BAB49C0F90A028FB5A46ADFF2129C581A75D257979D9743F2F10DB0821ACB9B9
[12496] 1509015009.975780: Preauth module encrypted_timestamp (2) (real) returned: 0/Success
[12496] 1509015009.975801: Produced preauth for next request: 133, 2
[12496] 1509015009.975852: Sending request (285 bytes) to DARKMASTERSIN.NET
[12496] 1509015009.978650: Resolving hostname kerberos.darkmastersin.net.
[12496] 1509015009.979589: Sending initial UDP request to dgram 2a02:2698:7023:eda8::36:88
[12496] 1509015010.980563: Sending initial UDP request to dgram 109.195.19.40:88
[12496] 1509015011.981455: Resolving hostname kerberos.darkmastersin.net.
[12496] 1509015011.982394: Initiating TCP connection to stream 2a02:2698:7023:eda8::36:88
[12496] 1509015012.982817: Initiating TCP connection to stream 109.195.19.40:88
[12496] 1509015012.984822: Sending TCP request to stream 109.195.19.40:88
[12496] 1509015013.79928: Received answer (727 bytes) from stream 109.195.19.40:88
[12496] 1509015013.80008: Terminating TCP connection to stream 2a02:2698:7023:eda8::36:88
[12496] 1509015013.80052: Terminating TCP connection to stream 109.195.19.40:88
[12496] 1509015013.81463: Response was from master KDC
[12496] 1509015013.81583: Processing preauth types: 19                                                                                                                                                                                      
[12496] 1509015013.81610: Selected etype info: etype rc4-hmac, salt "DARKMASTERSIN.NETsin", params ""                                                                                                                                       
[12496] 1509015013.81634: Produced preauth for next request: (empty)                                                                                                                                                                        
[12496] 1509015013.81662: AS key determined by preauth: rc4-hmac/2962                                                                                                                                                                       
[12496] 1509015013.81780: Decrypted AS reply; session key is: des3-cbc-sha1/61BD                                                                                                                                                            
[12496] 1509015013.81830: FAST negotiation: available                                                                                                                                                                                       
[12496] 1509015013.81884: Initializing KEYRING:persistent:500:500 with default princ sin@DARKMASTERSIN.NET                                                                                                                                  
[12496] 1509015013.81985: Storing sin@DARKMASTERSIN.NET -> krbtgt/DARKMASTERSIN.NET@DARKMASTERSIN.NET in KEYRING:persistent:500:500                                                                                                         
[12496] 1509015013.82108: Storing config in KEYRING:persistent:500:500 for krbtgt/DARKMASTERSIN.NET@DARKMASTERSIN.NET: fast_avail: yes                                                                                                      
[12496] 1509015013.82156: Storing sin@DARKMASTERSIN.NET -> krb5_ccache_conf_data/fast_avail/krbtgt\/DARKMASTERSIN.NET\@DARKMASTERSIN.NET@X-CACHECONF: in KEYRING:persistent:500:500                                                         
[12496] 1509015013.82259: Storing config in KEYRING:persistent:500:500 for krbtgt/DARKMASTERSIN.NET@DARKMASTERSIN.NET: pa_type: 2                                                                                                           
[12496] 1509015013.82298: Storing sin@DARKMASTERSIN.NET -> krb5_ccache_conf_data/pa_type/krbtgt\/DARKMASTERSIN.NET\@DARKMASTERSIN.NET@X-CACHECONF: in KEYRING:persistent:500:500

Comment 4 Vitaly Lipatov 2017-10-26 14:43:42 MSK

(В ответ на комментарий №3)
> Обеспечить логирование на клиенте - это задача клиента. Библиотека не может
> делать общий лог в заданное общее место под разными пользователями, да ещё и
> неявно.
> 
> Тем не менее сервер - тоже сам себе клиент. Не "на клиенте серверные
> настройки", а "на сервере - клиентские". Так что это общий конфиг.
Я к тому, что есть есть часть конфига, актуальная только на сервере, ей место в /etc/krb5.conf.d/server.conf

Потом было бы круто вписать про KRB5_TRACE=/dev/stdout в комментарии в конфиг, потому что
конфиг логичное место для включения логов. Я вот уже находил это KRB5_TRACE, и забыл напрочь.