ps ux always returns no btime in /proc/stat

[giggls]

Hello,

I'm using lxcfs (version 2.0.2 from debian-backports) on a Debian stable host running a vanilla Kernel (v 4.6.5).

Unfortunately I get "no btime in /proc/stat" inside all of my containers (Debian 7.x and 8.x).

I extracted the code in Question from procps sources, because btime does actually exist in /proc/stat (verified using grep btime /proc/stat.).

Digging further I found that fgets (see the code below) gives me zero bytes after reading "intr ..." which quits the while loop before btime has actually been reached.

So the bug in lxfs seems to be, that ps assumes, that fgets will never return zero until EOF of /proc/stat is reached. Unfortunately lxfs does not seem to make shure, that this assumption is always true.

Here is the code snippet from ps I have been using to debug this:

#include <stdio.h>
#include <stdlib.h>
#include <stdbool.h>
#include <string.h>
#define STAT_FILE "/proc/stat"


static char buf[8192];
char buf2[100];

unsigned long getbtime(void) {
    static unsigned long btime = 0;
    bool found_btime = false;
    FILE *f;

    if (btime)
        return btime;

    /* /proc/stat can get very large on multi-CPU systems so we
       can't use FILE_TO_BUF */
    if (!(f = fopen(STAT_FILE, "r"))) {
        fputs("can not open"STAT_FILE, stderr);
        fflush(NULL);
        exit(102);
    }
    /* gets seems to give 0 here in some cases inside containers
       before EOF is reached */ 
    while ((fgets(buf, sizeof buf, f))) {
        if (sscanf(buf, "btime %lu", &btime) == 1) {
            found_btime = true;
            break;
        }
    }
    fclose(f);

    if (!found_btime) {
        fputs("missing btime in " STAT_FILE "\n", stderr);
        exit(1);
    }

    return btime;
}

int main() {
  printf("%ld\n",getbtime());
  exit(0);
}

[hallyn]

I can't reproduce this on 4.4 and older kernels, don't have a 4.6 kernel handy. Can you show me the host's and container's /proc/stat contents?

[hallyn]

I also cannot reproduce this on Linux x1 4.6.0-10-generic #12-Ubuntu SMP Thu Aug 4 20:52:56 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

[giggls]

As I already wrote, the problem does not seem to be with the content of /proc/stat but with the fact that for some reason the loop terminates before btime has been read. If I replace /proc/stat in the code by a file "stat.txt" which I created using "cat /proc/stat >stat.txt" everything works fine.
I will attach the two files anyway.

[giggls]

/proc/stat from inside and outside container.
proc-stat-container.txt
proc-stat-host.txt

[hallyn]

I believe you... I was looking for some sort of empty line or something that might explain this.

As I said, 4.6 kernel in ubuntu 16.10 doesn't do this - ps ux works fine there. The two .txt files you appended are identical when wget'ed. So I'm sure there' something lxcfs is doing differently but I don't yet know what.

[giggls]

strace output looks somewhat strange inside the container:

open("/proc/stat", O_RDONLY)            = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f56a0576000
read(3, "cpu  22114483 25913 9453288 2297"..., 4096) = 4096
read(3, "", 4096)                       = 0
read(3, "", 4096)                       = 0
close(3)                                = 0
munmap(0x7f56a0576000, 4096)            = 0
write(2, "missing btime in /proc/stat\n", 28missing btime in /proc/stat
) = 28
exit_group(1)                           = ?
+++ exited with 1 +++

The 4096 seems to be crap IMO

Outside:

open("/proc/stat", O_RDONLY)            = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa94598a000
read(3, "cpu  22114354 25913 9453161 2297"..., 1024) = 1024
read(3, "u18 880297 1008 381294 95841960 "..., 1024) = 1024
read(3, " 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0"..., 1024) = 1024
read(3, " 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0"..., 1024) = 1024
read(3, " 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0"..., 1024) = 418
close(3)                                = 0
munmap(0x7fa94598a000, 4096)            = 0
fstat(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(136, 0), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa94598a000
write(1, "1470476668\n", 111470476668
)            = 11
exit_group(11)                          = ?
+++ exited with 11 +++

[giggls]

Aah wait, the second read is the problem, not the 4096 Why is this 0 and not 418?