Bug 1381649

Summary: perl-Net-FTPServer-1.125-7.fc26 FTBFS: tests fail with "Out of memory!"
Product: [Fedora] Fedora Reporter: Petr Pisar <ppisar>
Component: perl-Net-FTPServerAssignee: Petr Pisar <ppisar>
Status: CLOSED RAWHIDE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: rawhideCC: jplesnik, perl-devel, steve
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
URL: http://koji.fedoraproject.org/koji/taskinfo?taskID=15817695
Whiteboard:
Fixed In Version: perl-Net-FTPServer-1.125-8.fc26 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-12-23 09:18:40 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Petr Pisar 2016-10-04 16:04:34 UTC
perl-Net-FTPServer-1.125-7.fc26 fails to build in F26 because tests fail:

t/150commands.t .............. ok
Out of memory!
t/160portpasv.t .............. 
Failed 36/41 subtests 
Out of memory!
[...]
Test Summary Report
-------------------
t/160portpasv.t            (Wstat: 13 Tests: 5 Failed: 0)
  Non-zero wait status: 13
  Parse errors: Bad plan.  You planned 41 tests but ran 5.
t/160portzeroes.t          (Wstat: 13 Tests: 5 Failed: 0)
  Non-zero wait status: 13
  Parse errors: Bad plan.  You planned 23 tests but ran 5.
t/170ascii.t               (Wstat: 13 Tests: 9 Failed: 1)
  Failed test:  9
  Non-zero wait status: 13
  Parse errors: Bad plan.  You planned 18 tests but ran 9.
t/170files.t               (Wstat: 13 Tests: 11 Failed: 1)
  Failed test:  11
  Non-zero wait status: 13
  Parse errors: Bad plan.  You planned 36 tests but ran 11.
t/190list.t                (Wstat: 13 Tests: 41 Failed: 11)
  Failed tests:  30-38, 40-41
  Non-zero wait status: 13
  Parse errors: Bad plan.  You planned 82 tests but ran 41.
t/220restart.t             (Wstat: 13 Tests: 7 Failed: 1)
  Failed test:  7
  Non-zero wait status: 13
  Parse errors: Bad plan.  You planned 18 tests but ran 7.
t/230rename.t              (Wstat: 13 Tests: 6 Failed: 1)
  Failed test:  6
  Non-zero wait status: 13
  Parse errors: Bad plan.  You planned 11 tests but ran 6.
t/240abort.t               (Wstat: 13 Tests: 5 Failed: 0)
  Non-zero wait status: 13
  Parse errors: Bad plan.  You planned 16 tests but ran 5.
t/260welcometext.t         (Wstat: 256 Tests: 3 Failed: 1)
  Failed test:  3
  Non-zero exit status: 1
Files=44, Tests=432, 19 wallclock secs ( 0.23 usr  0.05 sys +  8.79 cusr  1.34 csys = 10.41 CPU)
Result: FAIL

Koschei reports this difference between working and failing build root:

        perl-Test-Simple 	1.302056-1.fc26 	> 	1.302059-1.fc26
	perl-podlators 	4.07-366.fc26 	> 	4.08-1.fc26
	perl-HTTP-Tiny 	0.064-1.fc26 	> 	0.068-1.fc26
	python3-setuptools 	27.1.2-1.fc26 	> 	27.3.0-1.fc26
	libnghttp2 	1.14.1-1.fc26 	> 	1.15.0-1.fc26
	libarchive 	3.2.1-3.fc26 	> 	3.2.1-4.fc26
	crypto-policies 	20160921-1.git75b9b04.... 	> 	20160926-1.git08b5501....
	make 	1:4.1-5.fc24 	> 	1:4.2.1-1.fc26
	openssl-libs 	1:1.0.2i-1.fc26 	> 	1:1.0.2j-1.fc26
	kernel-headers 	4.8.0-0.rc7.git4.1.... 	> 	4.8.0-0.rc8.git0.1....
	binutils 	2.27-8.fc26 	> 	2.27-9.fc26
	python2-setuptools 	27.1.2-1.fc26 	> 	27.3.0-1.fc26

But Koschei had some difficulties around that time. Maybe it's caused by perl-Encode update.

Comment 1 Petr Pisar 2016-12-22 14:39:30 UTC
A Net::FTPServer::InMem::Server server crashes on allocating memory in IO::Socket::INET->sysread():

$ strace -fq -e open,mmap,brk perl -Ilib  t/160portpasv.t 2>&1 | grep pid 
[pid 11895] open("/dev/null", O_RDONLY) = 4
[pid 11895] open("/usr/lib64/perl5/vendor_perl/auto/BSD/Resource/get_rlimits.al", O_RDONLY) = 4
[pid 11895] open("/usr/lib64/perl5/vendor_perl/auto/BSD/Resource/setrlimit.al", O_RDONLY) = 4
[pid 11895] open("/usr/lib64/perl5/vendor_perl/auto/BSD/Resource/_find_rlimit.al", O_RDONLY) = 4
[pid 11895] open("/etc/nsswitch.conf", O_RDONLY|O_CLOEXEC) = 4
[pid 11895] open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 4
[pid 11895] mmap(NULL, 48355, PROT_READ, MAP_PRIVATE, 4, 0) = 0x7f884823d000
[pid 11895] open("/lib64/libnss_files.so.2", O_RDONLY|O_CLOEXEC) = 4
[pid 11895] mmap(NULL, 2168568, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 4, 0) = 0x7f88443b5000
[pid 11895] mmap(0x7f88445bf000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 4, 0xa000) = -1 ENOMEM (Cannot allocate memory)
[pid 11895] open("/usr/share/zoneinfo/GMT", O_RDONLY|O_CLOEXEC) = 4
[pid 11895] open("/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 4
[pid 11895] open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 4
[pid 11895] mmap(NULL, 48355, PROT_READ, MAP_PRIVATE, 4, 0) = 0x7f884823d000
[pid 11895] open("/lib64/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = 4
[pid 11895] mmap(NULL, 2117832, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 4, 0) = 0x7f88441af000
[pid 11895] mmap(0x7f88443b3000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 4, 0x4000) = -1 ENOMEM (Cannot allocate memory)
[pid 11895] open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 4
[pid 11895] mmap(NULL, 48355, PROT_READ, MAP_PRIVATE, 4, 0) = 0x7f884823d000
[pid 11895] open("/lib64/libnss_myhostname.so.2", O_RDONLY|O_CLOEXEC) = 4
[pid 11895] mmap(NULL, 84192, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 4, 0) = 0x7f8848228000
[pid 11895] mmap(0x7f884823a000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 4, 0x11000) = -1 ENOMEM (Cannot allocate memory)
[pid 11895] open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 4
[pid 11895] mmap(NULL, 48355, PROT_READ, MAP_PRIVATE, 4, 0) = 0x7f884823d000
[pid 11895] open("/lib64/libnss_mymachines.so.2", O_RDONLY|O_CLOEXEC) = 4
[pid 11895] mmap(NULL, 290528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 4, 0) = 0x7f88481e1000
[pid 11895] mmap(0x7f8848224000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 4, 0x42000) = -1 ENOMEM (Cannot allocate memory)
[pid 11895] brk(NULL)                   = 0x3058000
[pid 11895] brk(0x3085000)              = 0x3058000
[pid 11895] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = -1 ENOMEM (Cannot allocate memory)
[pid 11895] brk(NULL)                   = 0x3058000
[pid 11895] brk(0x3085000)              = 0x3058000
[pid 11895] mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = -1 ENOMEM (Cannot allocate memory)
[pid 11895] mmap(NULL, 134217728, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f883c1af000
[pid 11895] mmap(NULL, 134217728, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f883c1af000
[pid 11895] mmap(NULL, 69632, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = -1 ENOMEM (Cannot allocate memory)
[pid 11894] --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=11894, si_uid=500} ---
[pid 11894] +++ killed by SIGPIPE +++

Comment 2 Petr Pisar 2016-12-22 14:50:24 UTC
But these are not any huge allocations. Something changes ulimits:

 core file size          (blocks, -c) 0
-data seg size           (kbytes, -d) unlimited
+data seg size           (kbytes, -d) 16384
 scheduling priority             (-e) 0
 file size               (blocks, -f) unlimited
 pending signals                 (-i) 3819
 max locked memory       (kbytes, -l) 64
 max memory size         (kbytes, -m) unlimited
-open files                      (-n) 1024
+open files                      (-n) 20
 pipe size            (512 bytes, -p) 8
 POSIX message queues     (bytes, -q) 819200
 real-time priority              (-r) 0
 stack size              (kbytes, -s) 8192
 cpu time               (seconds, -t) unlimited
-max user processes              (-u) 3819
+max user processes              (-u) 10
 virtual memory          (kbytes, -v) unlimited
 file locks                      (-x) unlimited

Comment 3 Petr Pisar 2016-12-22 15:04:02 UTC
Yes, this is it. Net::FTPServer limits heap size to 16384 KB by default. Probably some dependency started consume more memory at we now hit the limit in the tests.

Comment 4 Petr Pisar 2016-12-23 09:13:22 UTC
I will increase the memory limit.