Fork me on GitHub

From Siberia with love

How to find and fix bug in JRuby and don't go crazy (RU)

Данным постом я бы хотел показать какое количество работы может лежать за простым однострочным PR. Я постарался кратко изложить пошагово весь процесс от выявления проблемы, её исправления и до отправки результатов в upstream.

Итак, некоторое время назад я решил попробовать облачный сервис, предостовляющий ARM64 сервера. Запустив первый делом обновление RubyGems я увидел странную ошибку:

kes@labs:~$ ~/jruby-9.1.8.0/bin/jruby --dev -J-noverify -S gem update --system
Updating rubygems-update
Fetching: rubygems-update-2.6.12.gem (100%)
Successfully installed rubygems-update-2.6.12
Installing RubyGems 2.6.12
io/console on JRuby shells out to stty for most operations
ERROR:  While executing gem ... (ArgumentError)
    could not find a temporary directory

Странно… Проверил, что /tmp на самом деле существует:

kes@labs:~$ ls -al /
total 88
drwxr-xr-x  21 root root  4096 Apr 27 09:55 .
drwxr-xr-x  21 root root  4096 Apr 27 09:55 ..
<..>
drwxrwxrwt   9 root root 12288 May 10 08:55 tmp
<..>

Следующим шагом я перезапустил команду в VERBOSE и DEBUG режимах, но это дало ровным счётом никакой полезной информации. Далее я решил попробовать воспроизвести эту ошибку в REPL:

kes@labs:~$ ~/jruby-9.1.8.0/bin/jruby --dev -J-noverify -S irb
irb(main):001:0> require 'tmpdir'; Dir.tmpdir
ArgumentError: could not find a temporary directory
        from /home/kes/jruby-9.1.8.0/lib/ruby/stdlib/tmpdir.rb:35:in `tmpdir'
        from (irb):1:in `<eval>'
        from org/jruby/RubyKernel.java:1000:in `eval'
        from org/jruby/RubyKernel.java:1298:in `loop'
        from org/jruby/RubyKernel.java:1120:in `catch'
        from org/jruby/RubyKernel.java:1120:in `catch'
        from /home/kes/jruby-9.1.8.0/bin/jirb:13:in `<main>'

Ага! Это уже гораздо лучше. Можно пойти посмотреть сам код, где вывалилась ошибка:

require 'fileutils'
begin
  require 'etc.so'
rescue LoadError # rescue LoadError for miniruby
end

class Dir

  @@systmpdir ||= defined?(Etc.systmpdir) ? Etc.systmpdir : '/tmp'

  ##
  # Returns the operating system's temporary file path.

  def self.tmpdir
    if $SAFE > 0
      @@systmpdir.dup
    else
      tmp = nil
      [ENV['TMPDIR'], ENV['TMP'], ENV['TEMP'], @@systmpdir, '/tmp', '.'].each do |dir|
        next if !dir
        dir = File.expand_path(dir)
        if stat = File.stat(dir) and stat.directory? and stat.writable? and
            (!stat.world_writable? or stat.sticky?)
          tmp = dir
          break
        end rescue nil
      end
      raise ArgumentError, "could not find a temporary directory" unless tmp
      tmp
    end
  end
<..>

Каким-то образом у нас не находится tmp директория… Проверяем в консоли:

irb(main):002:0> require 'tmpdir'
=> true
irb(main):003:0> Etc.systmpdir
=> "/tmp"
irb(main):004:0> [ENV['TMPDIR'], ENV['TMP'], ENV['TEMP'], '/tmp'].map do |d|
irb(main):005:1*   next if !d
irb(main):006:1>   dir = File.expand_path(d)
irb(main):007:1>   stat = File.stat(dir)
irb(main):008:1>   [stat.directory?, stat.writable?, !stat.world_writable?, stat.sticky?]
irb(main):009:1> end
=> [nil, nil, nil, [false, false, true, false]]

Выходит так, что с точки зрения JRuby /tmp не директория, что наводит на мысли о баге. Я попробовал воспроизвести эту проблему на Linux x86_64 (и на macOS за одно):

kes@etehtsea:~$ jruby-9.1.8.0/bin/jruby -S irb
require 'tmpdir'; Dir.tmpdirirb(main):001:0> require 'tmpdir'; Dir.tmpdir
=> "/tmp"
irb(main):002:0> File.stat('/tmp').directory?
=> true

Так как проблема не воспроизводится, выходит что баг платформозависимый. Платформозависимый баг на JVM.

yey

Идём смотреть имплементацию File::Stat в JRuby.

@JRubyMethod(name = "directory?")
public RubyBoolean directory_p() {
    checkInitialized();
    return getRuntime().newBoolean(stat.isDirectory());
}

Так… что есть stat? Судя по всему, stat это инстанс jnr.posix.FileStat:

public class RubyFileStat extends RubyObject {
    <..>
    private FileStat stat;
    <..>
}

Значит проблема скорее всего не в самом JRuby, а в его зависимости jnr-posix. Туда и ныряем. Вспоминаю про то, что перед тем как начинать дебажить, можно попробовать запустить тесты. Едва ли их кто-то запускал на AARCH64. Пробуем:

Tests run: 7, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 2.415 sec <<< FAILURE! - in jnr.posix.FileStatTest
filestatDirectory(jnr.posix.FileStatTest)  Time elapsed: 0.021 sec  <<< FAILURE!
java.lang.AssertionError: null
        at org.junit.Assert.fail(Assert.java:86)
        at org.junit.Assert.assertTrue(Assert.java:41)
        at org.junit.Assert.assertTrue(Assert.java:52)
        at jnr.posix.FileStatTest.filestatDirectory(FileStatTest.java:196)

В данном случае падающий тест это хороший знак. Смотрим код теста:

@Test
public void filestatDirectory() throws Throwable {
    File f = File.createTempFile("stat", null).getParentFile();
    try {
        FileStat stat = posix.stat(f.getAbsolutePath());

        assertTrue(stat.isDirectory());
    } finally {
        f.delete();
    }
}

Прекрасно, похоже это наш случай. К этому моменту мы локализовали баг и можно со спокойной душой пойти и открыть issue в багтрекере jnr-posix и jruby. С другой стороны, можно откликнуться на вызов и попробовать починить этот баг в незнакомой кодобазе на непрофильном языке вдобавок с нативными вызовами через FFI. Я считаю, что чтобы прогрессировать, надо выходить из зоны комфорта, так что вызов принят.

challenge-accepted

Смотрим метод isDirectory() в BaseFileStat:

public boolean isDirectory() {
    return (mode() & S_IFMT) == S_IFDIR;
}

В данном случае меня интересует функция mode(). Самый простой способ посмотреть её значение, это воткнуть println в это место.

public boolean isDirectory() {
    System.out.println("Mode: " + mode());
    return (mode() & S_IFMT) == S_IFDIR;
}

Запускаю тест ещё раз:

<..>
Mode: 0
<..>

Очевидно, что mode() не должен быть 0. Смотрим как определён mode(). Для нашей платформы он в LinuxFileStat64:

public int mode() {
    return layout.st_mode.get(memory);
}

По сути класс LinuxFileStat64 это FFI враппер вокруг нативной stat64 структуры. В этот момент я занырнул в чтение исходников и документации.

Некоторое время спустя…

Структура stat64 заполняется вызовом нативной функции __xstat64().

@Override
public int stat(String path, FileStat stat) {
    if (use_xstat64) {
        try {
            return ((LinuxLibC) libc()).__xstat64(statVersion, path, stat);
        } catch (UnsatisfiedLinkError ex) {
            use_xstat64 = false;
            return old_stat(path, stat);
        }
    } else {
        return old_stat(path, stat);
    }
}

Для начала я решил проверить, что проблемы нет в нативном коде. Для этого сгодится немного переделанный пример из wikipedia.

#define _LARGEFILE_SOURCE 1

#include <stdio.h>
#include <stdlib.h>
#include <time.h>

#include <sys/types.h>
#include <pwd.h>
#include <grp.h>
#include <sys/stat.h>
#include <unistd.h>

void print_bytes(const void *object, size_t size)
{
    const unsigned char * const bytes = object;
    size_t i;

    printf("[ ");
    for(i = 0; i < size; i++)
    {
        printf("%02x ", bytes[i]);
    }
    printf("]\n");
}

int main(int argc, char *argv[])
{
        struct stat sb;

        if (argc < 2)
        {
                fprintf(stderr, "Usage: %s: file ...\n", argv[0]);
                exit(EXIT_FAILURE);
        }

        for (int i = 1; i < argc; i++)
        {
                if (-1 == __xstat64(0, argv[i], &sb))
                {
                        perror("stat()");
                        exit(EXIT_FAILURE);
                }

                printf("%s:\n", argv[i]);
                printf("\tdev: %u\n", sb.st_dev);
                printf("\tinode: %u\n", sb.st_ino);
                printf("\tmode: %o\n", sb.st_mode);
                printf("\tlinks: %d\n", sb.st_nlink);
                printf("\towner: %u\n", sb.st_uid);
                printf("\tgroup: %u\n", sb.st_gid);
                printf("\trdev: %u\n", sb.st_rdev);
                printf("\tsize: %ld\n", sb.st_size);
                printf("\tblksize: %d\n", sb.st_blksize);
                printf("\tblkcnt: %ld\n", sb.st_blocks);
                printf("\tatime: %s", ctime(&sb.st_atim.tv_sec));
                printf("\tmtime: %s", ctime(&sb.st_mtim.tv_sec));
                printf("\tctime: %s", ctime(&sb.st_ctim.tv_sec));
                printf("\n");

                printf("mode_t: %d\n", sizeof(mode_t));
                printf("dev_t: %d\n", sizeof(dev_t));
                printf("ino_t: %d\n", sizeof(ino_t));
                printf("nlink_t: %d\n", sizeof(nlink_t));
                printf("uid_t: %d\n", sizeof(uid_t));
                printf("gid_t: %d\n", sizeof(gid_t));
                printf("off_t: %d\n", sizeof(off_t));
                printf("blksize_t: %d\n", sizeof(blksize_t));
                printf("blkcnt_t: %d\n", sizeof(blkcnt_t));
                printf("struct timespec: %d\n", sizeof(struct timespec));
                printf("struct size: %d\n", sizeof(sb));

                print_bytes(&sb, sizeof(sb));
        }

        return 0;
}

Скомпилируем и запустим:

kes@labs:~$ cc -std=gnu11 xstat.c -o xstat && ./xstat /tmp
xstat.c: In function ‘main’:
xstat.c:39:13: warning: implicit declaration of function ‘__xstat64’ [-Wimplicit-function-declaration]
   if (-1 == __xstat64(0, argv[i], &sb))
             ^~~~~~~~~
/tmp:
        dev: 64768
        inode: 393217
        mode: 41777
        links: 9
        owner: 0
        group: 0
        rdev: 0
        size: 12288
        blksize: 4096
        blkcnt: 24
        atime: Wed May 10 08:58:36 2017
        mtime: Wed May 10 16:14:02 2017
        ctime: Wed May 10 16:14:02 2017

mode_t: 4
dev_t: 8
ino_t: 8
nlink_t: 4
uid_t: 4
gid_t: 4
off_t: 8
blksize_t: 4
blkcnt_t: 8
struct timespec: 16
struct size: 128
[ 00 fd 00 00 00 00 00 00 01 00 06 00 00 00 00 00 ff 43 00 00 09 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 30 00 00 00 00 00 00 00 10 00 00 00 00 00 00 18 00 00 00 00 00 00 00 3c d6 12 59 00 00 00 00 0e d5 8c 10 00 00 00 00 4a 3c 13 59 00 00 00 00 73 e9 5b 16 00 00 00 00 4a 3c 13 59 00 00 00 00 73 e9 5b 16 00 00 00 00 00 00 00 00 00 00 00 00 ]

Итак, в нативном коде с виду всё тип-топ. Для сравнения я скомпилировал и запустил этот же код на Linux x86_64:

/tmp:
	dev: 31
	inode: 9093
	mode: 41777
	links: 9
	owner: 0
	group: 0
	rdev: 0
	size: 680
	blksize: 4096
	blkcnt: 0
	atime: Wed May 10 08:36:05 2017
	mtime: Wed May 10 19:16:45 2017
	ctime: Wed May 10 19:16:45 2017

mode_t: 4
dev_t: 8
ino_t: 8
nlink_t: 8
uid_t: 4
gid_t: 4
off_t: 8
blksize_t: 8
blkcnt_t: 8
struct timespec: 16
struct size: 144
[ 1f 00 00 00 00 00 00 00 85 23 00 00 00 00 00 00 09 00 00 00 00 00 00 00 ff 43 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 a8 02 00 00 00 00 00 00 00 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c5 a6 12 59 00 00 00 00 1c 6d fa 06 00 00 00 00 ed 3c 13 59 00 00 00 00 7e 04 81 2c 00 00 00 00 ed 3c 13 59 00 00 00 00 7e 04 81 2c 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ]

Первое, что бросается в глаза это то, что размер структуры другой, а FFI маппинг у нас один. Чтобы подтвердить гипотезу, я накидал примерно аналогичную программу на Java:

import java.io.File;
import jnr.ffi.*;
import jnr.ffi.Runtime;
import jnr.ffi.annotations.Out;
import jnr.ffi.annotations.Transient;

public class HelloWorld {
    public static interface LibC {
        int puts(String s);
        int __xstat64(int statVersion, CharSequence path, @Out @Transient SB stat);
    }

    public static final class SB extends Struct {
        public SB(Runtime runtime) {
            super(runtime);
        }

        public final Signed64 st_dev = new Signed64();
        public final Signed64 st_ino = new Signed64();
        public final Signed64 st_nlink = new Signed64();
        public final Signed32 st_mode = new Signed32();
        public final Signed32 st_uid = new Signed32();
        public final Signed32 st_gid = new Signed32();
        public final Signed64 st_rdev = new Signed64();
        public final Signed64 st_size = new Signed64();
        public final Signed64 st_blksize = new Signed64();
        public final Signed64 st_blocks = new Signed64();
        public final Signed64 st_atime = new Signed64();     // Time of last access (time_t)
        public final Signed64 st_atimensec = new Signed64(); // Time of last access (nanoseconds)
        public final Signed64 st_mtime = new Signed64();     // Last data modification time (time_t)
        public final Signed64 st_mtimensec = new Signed64(); // Last data modification time (nanoseconds)
        public final Signed64 st_ctime = new Signed64();     // Time of last status change (time_t)
        public final Signed64 st_ctimensec = new Signed64(); // Time of last status change (nanoseconds)
        public final Signed64 __unused4 = new Signed64();
        public final Signed64 __unused5 = new Signed64();
        public final Signed64 __unused6 = new Signed64();
    }

    public static void main(String[] args) throws Throwable {
        LibC libc = LibraryLoader.create(LibC.class).load("c");
        File f = File.createTempFile("stat", null).getParentFile();
        Runtime runtime = Runtime.getRuntime(libc);
        SB stat = new SB(runtime);
        System.out.println("Struct size: " + Struct.size(stat));

        try {
            System.out.println(f.getAbsolutePath());
            int ret = libc.__xstat64(0, f.getAbsolutePath(), stat);
            System.out.println("Finished with: " + ret);

            System.out.println("\tdev: " + stat.st_dev.get());
            System.out.println("\tinode: " + stat.st_ino.get());
            System.out.println("\tmode: " + stat.st_mode.get());
            System.out.println("\tlinks: " + stat.st_nlink.get());
            System.out.println("\towner: " + stat.st_uid.get());
            System.out.println("\tgroup: " + stat.st_gid.get());
            System.out.println("\trdev: " + stat.st_rdev.get());
            System.out.println("\tsize: " + stat.st_size.get());
            System.out.println("\tblksize: " + stat.st_blksize.get());
            System.out.println("\tblkcnt: " + stat.st_blocks.get());
        } finally {
            f.delete();
        }
        libc.puts("Hello, World");
    }
}

Её вывод на AARCH64:

kes@labs:~$ javac -cp jnr-ffi-2.1.5.jar HelloWorld.java && java -cp asm-4.0_RC2.jar:jffi-1.2.15.jar:jnr-ffi-2.1.5.jar:. HelloWorld
Struct size: 144
/tmp
Finished with: 0
        dev: 64768
        inode: 393217
        mode: 0
        links: 38654723071
        owner: 0
        group: 0
        rdev: 0
        size: 12288
        blksize: 4096
        blkcnt: 24
Hello, World

Видно, что mode равняется нулю, а в поле links находится мусор. Судя по всему, под AARCH64 структура stat64 должна выглядеть иным образом. Казалось бы, что может быть проще: найти в документации описание структуры для нужной платформы и сделать аналогичный маппинг в jnr-posix? По факту я не нашёл никакого строгого описания, не говоря уже о том, что компилятор может делать паддинг внутри структуры (и в данном случае, если посчитать размер полей и размер фактической структуры, можно понять, что он присутствует). Так как я не имею особого опыта программирования на C лучшее, что я придумал на тот момент, это распечатать побайтово содержимое структуры и начать разбирать её в Hex Fiend в надежде понять как она устроена на самом деле.

Я поделился своей проблемой со знакомым программистом на C и он подсказал мне о существовании утилиты pahole, в которой можно посмотреть реальный вид структуры. Для этого надо пересобрать бинарник с отладочными символами добавив ключ -g на этапе компиляции. Далее запускаем:

kes@labs:~$ pahole xstat
<..>
struct stat {
        __dev_t                    st_dev;               /*     0     8 */
        __ino_t                    st_ino;               /*     8     8 */
        __mode_t                   st_mode;              /*    16     4 */
        __nlink_t                  st_nlink;             /*    20     4 */
        __uid_t                    st_uid;               /*    24     4 */
        __gid_t                    st_gid;               /*    28     4 */
        __dev_t                    st_rdev;              /*    32     8 */
        __dev_t                    __pad1;               /*    40     8 */
        __off_t                    st_size;              /*    48     8 */
        __blksize_t                st_blksize;           /*    56     4 */
        int                        __pad2;               /*    60     4 */
        /* --- cacheline 1 boundary (64 bytes) --- */
        __blkcnt_t                 st_blocks;            /*    64     8 */
        struct timespec            st_atim;              /*    72    16 */
        struct timespec            st_mtim;              /*    88    16 */
        struct timespec            st_ctim;              /*   104    16 */
        int                        __glibc_reserved[2];  /*   120     8 */
        /* --- cacheline 2 boundary (128 bytes) --- */

        /* size: 128, cachelines: 2, members: 16 */
};

Фантастика! На основе этого я починил FFI маппинг и перезапустил тестовый скрипт:

kes@labs:~$ javac -cp jnr-ffi-2.1.5.jar HelloWorld.java && java -cp asm-4.0_RC2.jar:jffi-1.2.15.jar:jnr-ffi-2.1.5.jar:. HelloWorld
Struct size: 128
/tmp
Finished with: 0
        dev: 64768
        inode: 393217
        mode: 17407
        links: 9
        owner: 0
        group: 0
        rdev: 0
        size: 12288
        blksize: 4096
        blkcnt: 24
Hello, World

Работает! Далее было необходимо проверить, что тест в jnr-posix больше не падает и ошибка в JRuby больше не воспроизводится. По результатам я открыл PRs в jnr-posix и JRuby проекты.

all_folks

Update:

Ага, не тут-то было. Одна вещь не давала мне покоя: когда я запускал pahole xstat на x86_64 платформе, я видел, что там тоже есть паддинг:

struct stat {
	__dev_t                    st_dev;               /*     0     8 */
	__ino_t                    st_ino;               /*     8     8 */
	__nlink_t                  st_nlink;             /*    16     8 */
	__mode_t                   st_mode;              /*    24     4 */
	__uid_t                    st_uid;               /*    28     4 */
	__gid_t                    st_gid;               /*    32     4 */
	int                        __pad0;               /*    36     4 */ /* <------ WAT /*
	__dev_t                    st_rdev;              /*    40     8 */
	__off_t                    st_size;              /*    48     8 */
	__blksize_t                st_blksize;           /*    56     8 */
	/* --- cacheline 1 boundary (64 bytes) --- */
	__blkcnt_t                 st_blocks;            /*    64     8 */
	struct timespec            st_atim;              /*    72    16 */
	struct timespec            st_mtim;              /*    88    16 */
	struct timespec            st_ctim;              /*   104    16 */
	__syscall_slong_t          __glibc_reserved[3];  /*   120    24 */
	/* --- cacheline 2 boundary (128 bytes) was 16 bytes ago --- */

	/* size: 144, cachelines: 3, members: 15 */
	/* last cacheline: 16 bytes */
};

Но тест на проверку размера есть и он проходит.

wat

Как оказалось, такой вопрос возник не у меня одного, но и у мейнтейнера jnr-posix enebo. cellscape подтвердил догадку, что jnr.ffi.StructLayout делает выравнивание автоматически.

После чего мапинг приобрёл финальный вид и пулл реквест был смержен.

Вот теперь точно всё, спасибо, если дочитали до конца.

blog comments powered byDisqus