Misconfigured LDAP authentication heavily impacts tar archive extraction performance
From Wiki-UX.info
Abstract
The following article explains a heavy negative performance impact on the tar archive extraction command introduced by misconfigured LDAP based user authentication.
A tusc trace of the affected tar execution, compared with a standard tar extraction, shows ioctl() and UNIX network sockets open when recoverying the user and group permissions of the archive. The network connection, in this case a LDAP authentication service, failed introducing a long delay between each file extraction from the tar archive.
Issue
Extracting a very small amount of data using the tar command takes much more than required.
For example:
# timex tar -xvf cst6.1.tar
x Config/current_connects, 0 bytes, 0 tape blocks
x Config/tktest.log, 0 bytes, 0 tape blocks
x Config/tksocket.lookup, 0 bytes, 0 tape blocks
x Config/rw_state, 2 bytes, 1 tape blocks
x Config/max_connects, 8 bytes, 1 tape blocks
x admin/pro_ini/edc/libedc.ini, 3433 bytes, 7 tape blocks
x admin/pro_ini/edc/libedc_noavs.ini, 3408 bytes, 7 tape blocks
x admin/pro_ini/edc/libedc_off.ini, 3536 bytes, 7 tape blocks
x admin/pro_ini/edc/libedc_cid.ini, 2900 bytes, 6 tape blocks
x admin/pro_ini/A4.ini, 6275 bytes, 13 tape blocks
x admin/pro_ini/dataset.ini, 9850 bytes, 20 tape blocks
x admin/pro_ini/edc_deferred.ini, 189 bytes, 1 tape blocks
x admin/pro_ini/not_tkagent.ini, 509 bytes, 1 tape blocks
x admin/pro_ini/W4.ini, 5900 bytes, 12 tape blocks
x admin/pro_ini/WB.ini, 5888 bytes, 12 tape blocks
x admin/pro_ini/B1.ini, 6020 bytes, 12 tape blocks
x admin/pro_ini/B4.ini, 6418 bytes, 13 tape blocks
x admin/pro_ini/deferedc.ini symbolic link to edc_deferred.ini
x admin/pro_ini/O1.ini, 5870 bytes, 12 tape blocks
x admin/pro_ini/O1void.ini, 5873 bytes, 12 tape blocks
x admin/pro_ini/K1.ini, 5620 bytes, 11 tape blocks
x admin/pro_ini/CST-urchicago.ini, 6341 bytes, 13 tape blocks
x admin/pro_ini/CST_CONSIGN.ini, 0 bytes, 0 tape blocks
x admin/pro_ini/LKTB1-group.ini, 6035 bytes, 12 tape blocks
x admin/pro_ini/LKTB1-phone.ini, 6036 bytes, 12 tape blocks
x admin/pro_ini/LKTB1-walkup.ini, 6036 bytes, 12 tape blocks
x admin/pro_ini/LKTB4-phone.ini, 6365 bytes, 13 tape blocks
x admin/pro_ini/LKTB4-walkup.ini, 6365 bytes, 13 tape blocks
x admin/pro_ini/MILEB3.ini, 6905 bytes, 14 tape blocks
x admin/pro_ini/MILEB3-1.ini, 6812 bytes, 14 tape blocks
x admin/pro_ini/mileb3.ini, 6341 bytes, 13 tape blocks
x admin/pro_ini/MILEB4-1.ini, 7050 bytes, 14 tape blocks
Command terminated abnormally.
real 1:40.86
user 0.01
sys 0.02
Note that files are very small and the total amount of data is trivial. Nonetheless, it took two minutes to complete the task.
Performing a tusc trace
Here it is the trace portion of the last extracted files, admin/pro_ini/MILEB3.ini:
access("admin", X_OK) ..................................................................................... = 0
access("admin/pro_ini", X_OK) ............................................................................. = 0
lstat64("admin/pro_ini/MILEB3.ini", 0x7f7f0b90) ........................................................... = 0
open("admin/pro_ini/MILEB3.ini", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) .............................. = 7
write(2, "x a d m i n / ", 8) ........................................................................... = 8
write(2, "p r o _ i n i / ", 8) ........................................................................... = 8
write(2, "M I L E B 3 . i ", 8) ........................................................................... = 8
write(2, "n i ", 2) ....................................................................................... = 2
write(2, ", 6 9 0 5 b ", 8) ........................................................................... = 8
write(2, "y ", 1) ......................................................................................... = 1
write(2, "t e s , 1 4 ", 8) ........................................................................... = 8
write(2, "t ", 1) ......................................................................................... = 1
write(2, "a p e b l o c ", 8) ........................................................................... = 8
write(2, "k ", 1) ......................................................................................... = 1
write(2, "s \n", 2) ....................................................................................... = 2
write(7, "# # # C S T 5 B o x O f f ".., 512) ....................................................... = 512
write(7, "E N T _ I D = M I L E I D E ".., 512) ....................................................... = 512
write(7, ". t x t \nT O R D E R _ A C T I ".., 512) ....................................................... = 512
write(7, " p r n _ t i x . t x t \nU S E ".., 512) ....................................................... = 512
read(4, "R M A T = 3 \nU S E R _ T I ".., 10240) ...................................................... = 10240
write(7, "R M A T = 3 \nU S E R _ T I ".., 512) ....................................................... = 512
write(7, "S E R _ S U M M A R Y _ C A R D ".., 512) ....................................................... = 512
write(7, "W I T H _ N O _ T I X _ I N _ A ".., 512) ....................................................... = 512
write(7, "Y \nU S E R _ A C C E S S _ P H ".., 512) ....................................................... = 512
write(7, "S _ O N _ E X I T = N \nA C ".., 512) ....................................................... = 512
write(7, "_ E V E N T _ L O O K U P = ".., 512) ....................................................... = 512
write(7, "D U E = Y \nU S E R _ A L L ".., 512) ....................................................... = 512
write(7, "_ A C C E S S _ C O N T R O L _ ".., 512) ....................................................... = 512
write(7, "E D _ T I C K E T S = Y \nU ".., 512) ....................................................... = 512
write(7, "R _ A C C E S S _ L O O K U P _ ".., 249) ....................................................... = 249
close(7) .................................................................................................. = 0
time(NULL) ................................................................................................ = 1267545473
utime("admin/pro_ini/MILEB3.ini", 0x7f7f09fc) ............................................................. = 0
getpid() .................................................................................................. = 15167 (15166)
open("/etc/group", O_RDONLY, 0666) ........................................................................ = 7
ioctl(7, TCGETA, 0x7f7f2488) .............................................................................. ERR#25 ENOTTY
read(7, "r o o t : : 0 : r o o t \no t h ".., 8192) ....................................................... = 305
read(7, 0x40017508, 8192) ................................................................................. = 0
close(7) .................................................................................................. = 0
time(NULL) ................................................................................................ = 1267545473
getpid() .................................................................................................. = 15167 (15166)
poll(0x7f7f2108, 1, 0) .................................................................................... = 1
sendto(6, "f2\0\0010204\0\0\0\0\0\v\0\01c80".., 38, 0, 0x7aed9e18, 0x1d) .................................. = 38
poll(0x7f7f23b8, 1, 200) .................................................................................. = 1
recv(6, "f2\0\0010204\n\0\0\0\0\0\0\0\0\0".., 32768, 0) ................................................... = 27
socket2(1, 1, 0) .......................................................................................... = 7
connect(7, 0x7f7f209c, 94) ................................................................................ ERR#239 ECONNREFUSED
close(7) .................................................................................................. = 0
getpid() .................................................................................................. = 15167 (15166)
open("/etc/passwd", O_RDONLY, 0666) ....................................................................... = 7
ioctl(7, TCGETA, 0x7f7f1c88) .............................................................................. ERR#25 ENOTTY
read(7, "r o o t : j D Z s Q C k h Q V Y ".., 8192) ....................................................... = 1598
read(7, 0x40016d08, 8192) ................................................................................. = 0
close(7) .................................................................................................. = 0
time(NULL) ................................................................................................ = 1267545473
getpid() .................................................................................................. = 15167 (15166)
poll(0x7f7f1908, 1, 0) .................................................................................... = 1
sendto(6, "f2\0\0010201\0\0\0\0\0\t\0\0\b\0".., 36, 0, 0x7aed9e18, 0x1d) .................................. = 36
poll(0x7f7f1bb8, 1, 200) .................................................................................. = 1
recv(6, "f2\0\0010201\n\0\0\0\0\0\0\0\0\0".., 32768, 0) ................................................... = 27
socket2(1, 1, 0) .......................................................................................... = 7
connect(7, 0x7f7f189c, 94) ................................................................................ ERR#239 ECONNREFUSED
close(7) .................................................................................................. = 0
chown("admin/pro_ini/MILEB3.ini", 12481, 106) ............................................................. = 0
chmod("admin/pro_ini/MILEB3.ini", 0666) ................................................................... = 0
getpid() .................................................................................................. = 15167 (15166)
open("/etc/group", O_RDONLY, 0666) ........................................................................ = 7
ioctl(7, TCGETA, 0x7f7f2508) .............................................................................. ERR#25 ENOTTY
read(7, "r o o t : : 0 : r o o t \no t h ".., 8192) ....................................................... = 305
read(7, 0x40017508, 8192) ................................................................................. = 0
close(7) .................................................................................................. = 0
time(NULL) ................................................................................................ = 1267545473
getpid() .................................................................................................. = 15167 (15166)
poll(0x7f7f2188, 1, 0) .................................................................................... = 1
sendto(6, "f2\0\0010204\0\0\0\0\0\f\0\01c80".., 39, 0, 0x7aed9e18, 0x1d) .................................. = 39
poll(0x7f7f2438, 1, 200) .................................................................................. = 1
recv(6, "f2\0\0010204\n\0\0\0\0\0\0\0\0\0".., 32768, 0) ................................................... = 27
socket2(1, 1, 0) .......................................................................................... = 7
connect(7, 0x7f7f211c, 94) ................................................................................ ERR#239 ECONNREFUSED
close(7) .................................................................................................. = 0
getpid() .................................................................................................. = 15167 (15166)
open("/etc/passwd", O_RDONLY, 0666) ....................................................................... = 7
ioctl(7, TCGETA, 0x7f7f1d08) .............................................................................. ERR#25 ENOTTY
read(7, "r o o t : j D Z s Q C k h Q V Y ".., 8192) ....................................................... = 1598
lseek(7, 4294967241, SEEK_CUR) ............................................................................ = 1543
close(7) .................................................................................................. = 0
Compare it with the normal execution of the following synthetic test of 1 MB of random data:
# perl -e 'srand(time() ^ $$); while (1) { print chr(int(rand() * 255)); }' | dd of=/var/tmp/1MB.dd bs=1k count=1024
1024+0 records in
1024+0 records out
# ls -l /var/tmp/1MB.dd
-rw-r--r-- 1 root sys 1048576 Mar 1 19:24 /var/tmp/1MB.dd
# tar -cvf /var/tmp/1MB.tar /var/tmp/1MB.dd
a /var/tmp/1MB.dd 2048 blocks
# gzip /var/tmp/1MB.tar
# ls -l /var/tmp/1MB.tar.gz
-rw-r--r-- 1 root sys 1048974 Mar 1 19:24 /var/tmp/1MB.tar.gz
# timex tusc -o /tmp/gzcat.tusc gzcat /var/tmp/1MB.tar.gz | tusc -o /tmp/tar.tusc tar -xf -
real 0.45
user 0.01
sys 0.01
Note that after the last read() / write() system calls, the process only performs the following actions:
read(4, "\na8d6a2` fbd8b6~ fdk a f104bc! ".., 512) ....... = 512
write(6, "\na8d6a2` fbd8b6~ fdk a f104bc! ".., 512) ...... = 512
close(6) ................................................. = 0
time(NULL) ............................................... = 1267551955
utime("/var/tmp/1MB.dd", 0x77ff0edc) ..................... = 0
getpid() ................................................. = 8029 (8028)
stat("/etc/default/lugname", 0x77ff3ff8) ................. ERR#2 ENOENT
poll(0x77ff2f30, 1, 0) ................................... = 1
sendto(5, "\0\0\00 \0\0\001\0\0\002\0\0\004".., 48, 0, 0x77fdcff8, 0x19) = 48
poll(0x77ff2f30, 1, 1000) ................................ = 1
recvfrom(5, "\0\0\0! \0\0\002\0\0\0\0\0\0\011".., 2064, 0, 0x77ff30f8, 0x77ff30f4) = 33
getpid() ................................................. = 8029 (8028)
stat("/etc/default/lugname", 0x77ff37f8) ................. ERR#2 ENOENT
poll(0x77ff2730, 1, 0) ................................... = 1
sendto(5, "\0\0\00 \0\0\001\0\0\003\0\0\002".., 48, 0, 0x77fdcff8, 0x19) = 48
poll(0x77ff2730, 1, 1000) ................................ = 1
recvfrom(5, "\0\0\0. \0\0\003\0\0\0\0\0\0\01e".., 2064, 0, 0x77ff28f8, 0x77ff28f4) = 46
chown("/var/tmp/1MB.dd", 0, 3) ........................... = 0
chmod("/var/tmp/1MB.dd", 0644) ........................... = 0
read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0".., 512) ....... = 512
close(4) ................................................. = 0
unlink("/tmp/tarXXXXXX") ................................. ERR#2 ENOENT
getpid() ................................................. = 8029 (8028)
unlink("/var/spool/sockets/pwgr/client8029") ............. = 0
exit(0) .................................................. WIFEXITED(0)
Analysis
1. The ioctl() error is non fatal because the user and group data are actually read from the file handler of both /etc/passwd and /etc/group. However, it is an indication that something different from plain file based authentication has been at work in the affected system:
- man ioctl()
[ENOTTY] The request is not appropriate to the selected
device
- man errno(2)
[ENOTTY] Not a typewriter. The (ioctl()) command is
inappropriate to the selected device type.
2. A socket2() connect error follows the ioctl():
- man connect(2)
[ECONNREFUSED] The attempt to connect was forcefully
rejected.
- man errno(2)
[ECONNREFUSED] Connection refused. No connection could be made
because the target machine actively refused it. This
usually results from trying to connect to a service
that is inactive on the foreign host.
The delay is introduced by the ioctl() and the timing out of the socket2() connection.
Further investigation discovered that an incorrect PAM LDAP-based implementantion of user authentication was previously introduced in the system. The failed authentication delays the user and group authentication. After disabling the affected service, the performance problem was corrected.
