Package: netatalk
Severity: normal
Hi,
I was in doubt whether the following is bug or not, so I decided to
write to you directly.
I have freshly installed Debian/Squeeze (armel architecture) on NAS
QNAP TS-210. NAS has static address 192.168.1.3. On other side I have
iMac with Mac OS X 10.6.3 and static address 192.168.1.4.
netatalk is built with libgrypt, i. e. without ssl, and DHX2
authentification is used. The problem: the DHX2 authentification always
takes about 21 seconds and sometimes longer:
May 23 17:31:05 MED-ES-NAS afpd[1101]: DHX2 login: timemachine
^^^^^^^^
May 23 17:31:26 MED-ES-NAS afpd[1101]: PAM DHX2: PAM Success
^^^^^^^^
I think that is very long, isn't it? At the same time, guest
authentification proceeds immediately. A full log with DHX2
authentification below. I have created the user 'timemachine' with
password 'timemachine' and tried to connect to afp://192.168.1.3 from
iMac:
May 23 17:29:04 MED-ES-NAS afpd[1021]: AFP/TCP started, advertising
192.168.1.3:548 (2.1)
May 23 17:29:04 MED-ES-NAS afpd[1021]: uam: uams_guest.so loaded
May 23 17:29:04 MED-ES-NAS afpd[1021]: uam: uams_dhx2.so loaded
May 23 17:29:04 MED-ES-NAS afpd[1021]: uam: "DHX2" available
May 23 17:29:04 MED-ES-NAS afpd[1021]: uam: "No User Authent" available
May 23 17:29:04 MED-ES-NAS afpd[1021]: Registering CNID module [last]
May 23 17:29:04 MED-ES-NAS afpd[1021]: Registering CNID module [dbd]
May 23 17:29:04 MED-ES-NAS afpd[1021]: Registering CNID module [tdb]
May 23 17:29:13 MED-ES-NAS kernel: [ 58.986748] eth0: no IPv6 routers present
May 23 17:30:58 MED-ES-NAS afpd[1099]: AFP/TCP session from 192.168.1.4:49163
May 23 17:30:58 MED-ES-NAS afpd[1021]: server_child[1] 1099 done
May 23 17:31:05 MED-ES-NAS afpd[1101]: AFP/TCP session from 192.168.1.4:49164
May 23 17:31:05 MED-ES-NAS afpd[1101]: DHX2 login: timemachine
May 23 17:31:26 MED-ES-NAS afpd[1101]: PAM DHX2: PAM Success
May 23 17:31:26 MED-ES-NAS afpd[1101]: DHX2: PAM Auth OK!
May 23 17:31:26 MED-ES-NAS afpd[1101]: login timemachine (uid 1001, gid 1001)
AFP3.2
May 23 17:31:26 MED-ES-NAS afpd[1101]: volume "TMBackup" does not support
Extended Attributes, using ea:ad instead
May 23 17:31:26 MED-ES-NAS afpd[1101]: volume "Public" does not support
Extended Attributes, using ea:ad instead
May 23 17:31:26 MED-ES-NAS afpd[1101]: Volume /share/Public use CNID scheme dbd.
May 23 17:31:26 MED-ES-NAS afpd[1101]: localhost:4700
May 23 17:31:26 MED-ES-NAS afpd[1104]: AFP/TCP session from 192.168.1.4:49165
May 23 17:31:26 MED-ES-NAS afpd[1021]: server_child[1] 1104 done
May 23 17:31:26 MED-ES-NAS cnid_dbd[1105]: Set syslog logging to level: LOG_NOTE
May 23 17:31:46 MED-ES-NAS afpd[1101]: dbd_rpc: Error reading header from fd
(db_dir /share/Public): Resource temporarily unavailable
May 23 17:31:52 MED-ES-NAS afpd[1106]: AFP/TCP session from 192.168.1.4:49166
May 23 17:31:52 MED-ES-NAS afpd[1021]: server_child[1] 1106 done
May 23 17:31:52 MED-ES-NAS afpd[1107]: AFP/TCP session from 192.168.1.4:49167
May 23 17:31:52 MED-ES-NAS afpd[1021]: server_child[1] 1107 done
May 23 17:31:56 MED-ES-NAS afpd[1101]: logout timemachine
May 23 17:31:56 MED-ES-NAS afpd[1101]: 2.33KB read, 2.88KB written
May 23 17:31:56 MED-ES-NAS afpd[1021]: server_child[1] 1101 done
netatalk configuration
======================
uname -a:
--------
Linux MED-ES-NAS 2.6.32-3-kirkwood #1 Sat Feb 27 14:27:55 UTC 2010 armv5tel
GNU/Linux
/etc/hostname:
--------------
MED-ES-NAS
/etc/hosts:
-----------
127.0.0.1 localhost
192.168.1.3 MES-ES-NAS
/etc/pam.d/netatalk:
--------------------
#%PAM-1.0
@include common-auth
@include common-account
@include common-password
@include common-session
/etc/netatalk/atalkd.conf:
--------------------------
eth0
/etc/netatalk/afpd.conf:
------------------------
- -transall -uamlist uams_guest.so,uams_dhx2.so -nosavepassword
/etc/netatalk/AppleVolumes.default:
-----------------------------------
# The line below sets some DEFAULT, starting with Netatalk 2.1.
:DEFAULT: options:upriv,usedots
/share/TMBackup/ "TMBackup" options:tm perm:0770
/share/Public/ "Public"
/etc/default/netatalk.conf:
---------------------------
AFPD_MAX_CLIENTS=20
ATALK_NAME=`/bin/hostname --short`
ATALK_MAC_CHARSET='MAC_ROMAN'
ATALK_UNIX_CHARSET='LOCALE'
AFPD_GUEST=nobody
ATALKD_RUN=no
PAPD_RUN=no
TIMELORD_RUN=no
A2BOOT_RUN=no
CNID_METAD_RUN=yes
AFPD_RUN=yes
ATALK_BGROUND=no
export ATALK_MAC_CHARSET
export ATALK_UNIX_CHARSET
I think about possible reading from /dev/random during authentification
process. Indeed, the following command blocks reading for some time (in
this case for 13 seconds):
# dd if=/dev/random of=/root/random bs=1 count=16
16+0 records in
16+0 records out
16 bytes (16 B) copied, 12,9026 s, 0,0 kB/s
Because this is NAS, there is no interaction with user's input devices
and there is not so much hardware activity, so an entropy pool is
depleted very quickly. To overcome that I have installed rng-tools and
configured it to use /dev/urandom as random numbers source and verified
the reading of the long sequences from /dev/random again -- all becomes
OK with reading from /dev/random. Here the config from
/etc/default/rng-tools
HRNGDEVICE=/dev/urandom
RNGDOPTIONS="--fill-watermark=89% --feed-interval=2 --random-device=/dev/random"
However, these actions don't solve the authentification time problem.
Next, I have enabled debug log. During this time gap we have the
AFPERR_AUTHCONT errors, but at the end we have a success:
Май 23 23:50:31.298497 afpd[1433] {uams_dhx2_pam.c:350} (I:UAMSDaemon): DHX2
login: timemachine
Май 23 23:50:31.849598 afpd[1434] {dsi_tcp.c:230} (I:Default): AFP/TCP session
from 192.168.1.4:49173
Май 23 23:50:31.860184 afpd[1422] {server_child.c:389} (I:Default):
server_child[1] 1434 done
Май 23 23:50:40.419614 afpd[1435] {dsi_tcp.c:230} (I:Default): AFP/TCP session
from 192.168.1.4:49174
Май 23 23:50:40.421016 afpd[1435] {afp_dsi.c:437} (D5:AFPDaemon): <== Start AFP
command: AFP_LOGIN_EXT
Май 23 23:50:40.424758 afpd[1435] {uams_dhx2_pam.c:350} (I:UAMSDaemon): DHX2
login: timemachine
Май 23 23:50:47.271156 afpd[1433] {afp_dsi.c:444} (D5:AFPDaemon): ==> Finished
AFP command: AFP_LOGIN_EXT -> AFPERR_AUTHCONT
Май 23 23:50:47.289028 afpd[1433] {afp_dsi.c:437} (D5:AFPDaemon): <== Start AFP
command: AFP_LOGINCONT
Май 23 23:50:47.537950 afpd[1433] {afp_dsi.c:444} (D5:AFPDaemon): ==> Finished
AFP command: AFP_LOGINCONT -> AFPERR_AUTHCONT
Май 23 23:50:47.548470 afpd[1433] {afp_dsi.c:437} (D5:AFPDaemon): <== Start AFP
command: AFP_LOGINCONT
Май 23 23:50:54.442052 afpd[1435] {afp_dsi.c:444} (D5:AFPDaemon): ==> Finished
AFP command: AFP_LOGIN_EXT -> AFPERR_AUTHCONT
Май 23 23:50:54.460068 afpd[1435] {afp_dsi.c:437} (D5:AFPDaemon): <== Start AFP
command: AFP_LOGINCONT
Май 23 23:50:54.590739 afpd[1435] {afp_dsi.c:444} (D5:AFPDaemon): ==> Finished
AFP command: AFP_LOGINCONT -> AFPERR_AUTHCONT
Май 23 23:50:54.591769 afpd[1435] {afp_dsi.c:437} (D5:AFPDaemon): <== Start AFP
command: AFP_LOGINCONT
Май 23 23:50:57.571367 afpd[1433] {uams_dhx2_pam.c:228} (I:UAMSDaemon): PAM
DHX2: PAM Success
Май 23 23:50:57.937772 afpd[1433] {uams_dhx2_pam.c:684} (I:UAMSDaemon): DHX2:
PAM Auth OK!
--
To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmas...@lists.debian.org
