From owner-freebsd-current@freebsd.org Thu Mar 9 20:08:03 2017 Return-Path: Delivered-To: freebsd-current@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id AA700D04A5C for ; Thu, 9 Mar 2017 20:08:03 +0000 (UTC) (envelope-from gergely.czuczy@harmless.hu) Received: from marvin.harmless.hu (marvin.harmless.hu [195.56.55.204]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 6AF39100B for ; Thu, 9 Mar 2017 20:08:02 +0000 (UTC) (envelope-from gergely.czuczy@harmless.hu) Received: from 178-164-145-249.pool.digikabel.hu ([178.164.145.249] helo=[10.219.16.1]) by marvin.harmless.hu with esmtpsa (TLSv1.2:ECDHE-RSA-AES128-GCM-SHA256:128) (Exim 4.88 (FreeBSD)) (envelope-from ) id 1cm4Lv-000MIq-JV for freebsd-current@freebsd.org; Thu, 09 Mar 2017 20:07:59 +0000 Subject: Re: process killed: text file modification To: freebsd-current@freebsd.org References: <646c1395-9482-b214-118c-01573243ae5a@harmless.hu> <45436522-77df-f894-0569-737a6a74958f@harmless.hu> <55189643.aaZPuY77s8@ralph.baldwin.cx> <3ed3e4a3-23af-7267-39f1-9090093c9c1e@harmless.hu> From: Gergely Czuczy Message-ID: <5ac94b9a-7ced-9eff-d746-7dddaaeca516@harmless.hu> Date: Thu, 9 Mar 2017 21:07:59 +0100 User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:45.0) Gecko/20100101 Thunderbird/45.8.0 MIME-Version: 1.0 In-Reply-To: <3ed3e4a3-23af-7267-39f1-9090093c9c1e@harmless.hu> Content-Type: text/plain; charset=windows-1252; format=flowed Content-Transfer-Encoding: 7bit X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 09 Mar 2017 20:08:03 -0000 On 2017. 03. 09. 20:47, Gergely Czuczy wrote: > > > On 2017. 03. 09. 19:44, John Baldwin wrote: >> On Thursday, March 09, 2017 03:31:56 PM Gergely Czuczy wrote: >>> [+freebsd-fs] >>> >>> >>> On 2017. 03. 09. 14:20, Gergely Czuczy wrote: >>>> On 2017. 03. 09. 11:27, Gergely Czuczy wrote: >>>>> Hello, >>>>> >>>>> I'm trying to build a few things from ports on an rpi3, the ports >>>>> collection is mounted over NFS from another machine. When it's trying >>>>> to build pkg i'm getting the error message in syslog: >>>>> >>>>> rpi3 kernel: pid 4451 (sh), uid 0, was killed: text file modification >>>>> >>>>> The report to pkg@: >>>>> https://lists.freebsd.org/pipermail/freebsd-pkg/2017-March/002048.html >>>>> >>>>> >>>>> In ports-mgmt/pkg's config.log It fails at the following entry: >>>>> configure:3726: checking whether we are cross compiling >>>>> configure:3734: cc -o conftest -O2 -pipe -Wno-error >>>>> -fno-strict-aliasing conftest.c >&5 >>>>> configure:3738: $? = 0 >>>>> configure:3745: ./conftest >>>>> configure:3749: $? = 137 >>>>> configure:3756: error: in >>>>> `/usr/ports/ports-mgmt/pkg/work/pkg-1.10.0': >>>>> configure:3760: error: cannot run C compiled programs. >>>>> If you meant to cross compile, use `--host'. >>>>> See `config.log' for more details >>>>> >>>>> # uname -a >>>>> FreeBSD rpi3 12.0-CURRENT FreeBSD 12.0-CURRENT #0 r314949: Thu Mar 9 >>>>> 08:58:46 CET 2017 >>>>> aegir@marvin.harmless.hu:/tank/rpi3/crochet/work/obj/arm64.aarch64/tank/rpi3/src/sys/AEGIR >>>>> >>>>> arm64 >>>> So far, a few additions: >>>> Time is synced between the NFS server and the client. >>>> it's an open() call which is getting the kill, and it's not the file >>>> what's being opened, but the process executing it. >>>> Here's a simple code that reproduces it: >>>> #include >>>> >>>> int main() { >>>> >>>> FILE *f = fopen ("/bar", "w"); >>>> >>>> fclose(f); >>>> return 0; >>>> } >>>> >>>> Conditions to reproduce it: >>>> - The resulting binary must be executed from the nfs mount >>>> - The binary must be built after mounting the NFS share. >>>> >>>> I haven't tried building it on a different host, I don't have access >>>> to multiple RPis. Also, if I build the binary, umount/remount the NFS >>>> mount point, which has the binary, execute it, then it works. >>>> >>>> I've also tried this with the raspbsd.org's image, I could reproduce >>>> it as well. >>>> >>>> Another interesting thing is, when I first booted the RPi up, the NFS >>>> server was a 10.2-STABLE, and later got updated to 11-STABLE. While it >>>> was 10.2 I've tried to build some port, and I don't remember having >>>> this issue. >>>> >>>> So, could someone please help me figure this out and fix it? This >>>> stuff should work pretty much. >>>> >>> So, this error message comes from here: >>> https://svnweb.freebsd.org/base/head/sys/fs/nfsclient/nfs_clbio.c?revision=314436&view=markup#l1674 >>> >>> >>> It's the NFS_TIMESPEC_COMPARE(&np->n_mtime, &np->n_vattr.na_mtime) >>> comparision that fails, np should be the NFS node structure, from the >>> vnode's v_data, and n_vattr is the attribute cache. As I've seen these >>> two are being updated together, so I don't really see by the code why >>> they might differ. Could someone please take a look at it, with more >>> experience in the NFS code? -czg >> Can you print out the two mtimes? I wonder if what's happening is that >> your server uses different granularity (for example just seconds) than >> your client, so on the client we generate a timestamp with a non-zero >> nanoseconds but when the server receives that timestamp it "truncates" >> it. During open() we forcefully re-fetch the timestamp (for CTO >> consistency) and then notice it doesn't match. For now I would start >> with comparing the timestamps and maybe the vfs.timestamp_precision >> sysctls on client and server (if server is a FreeBSD box). > Here are the time values: > Mar 9 19:46:01 rpi3 kernel: np->n_mtime: -3298114786344 + > -3298114786336 &np->n_vattr.na_mtime: -3298114786616 + -3298114786608 > Mar 9 19:46:01 rpi3 kernel: pid 912 (csh), uid 0, was killed: text > file modification > Mar 9 19:46:01 rpi3 kernel: np->n_mtime: -3298114786344 + > -3298114786336 &np->n_vattr.na_mtime: -3298114786616 + -3298114786608 > Mar 9 19:46:01 rpi3 kernel: pid 912 (csh), uid 0, was killed: text > file modification > > Printed this way: > printf("np->n_mtime: %ji + %ji > &np->n_vattr.na_mtime: %ji + %ji", > (intmax_t)(&np->n_mtime.tv_sec), > (intmax_t)(&np->n_mtime.tv_nsec), > (intmax_t)(&np->n_vattr.na_mtime.tv_sec), > (intmax_t)(&np->n_vattr.na_mtime.tv_nsec)); Sorry, I made a typo there. Here's it now: Mar 9 20:05:35 rpi3 kernel: np->n_mtime: 1489089935 + 219323000 &np->n_vattr.na_mtime: 1489089935 + 221438000 Mar 9 20:05:35 rpi3 kernel: pid 847 (csh), uid 0, was killed: text file modification Mar 9 20:05:35 rpi3 kernel: np->n_mtime: 1489089935 + 219323000 &np->n_vattr.na_mtime: 1489089935 + 221438000 Mar 9 20:05:35 rpi3 kernel: pid 847 (csh), uid 0, was killed: text file modification That's a difference of 2115 micro seconds.