Re: ppc elf_map breakage with MAP_FIXED_NOREPLACE

[Anshuman Khandual <khandual@linux.vnet.ibm.com>]

On 01/24/2018 02:35 PM, Michal Hocko wrote:
> On Wed 24-01-18 10:39:41, Anshuman Khandual wrote:
>> On 01/23/2018 09:36 PM, Michal Hocko wrote:
>>> On Tue 23-01-18 21:28:28, Anshuman Khandual wrote:
>>>> On 01/23/2018 06:15 PM, Michal Hocko wrote:
>>>>> On Tue 23-01-18 16:55:18, Anshuman Khandual wrote:
>>>>>> On 01/17/2018 01:37 PM, Michal Hocko wrote:
>>>>>>> On Thu 11-01-18 15:38:37, Anshuman Khandual wrote:
>>>>>>>> On 01/09/2018 09:43 PM, Michal Hocko wrote:
>>>>>>> [...]
>>>>>>>>> Did you manage to catch _who_ is requesting that anonymous mapping? Do
>>>>>>>>> you need a help with the debugging patch?
>>>>>>>> Not yet, will get back on this.
>>>>>>> ping?
>>>>>> Hey Michal,
>>>>>>
>>>>>> Missed this thread, my apologies. This problem is happening only with
>>>>>> certain binaries like 'sed', 'tmux', 'hostname', 'pkg-config' etc. As
>>>>>> you had mentioned before the map request collision is happening on
>>>>>> [10030000, 10040000] and [10030000, 10040000] ranges only which is
>>>>>> just a single PAGE_SIZE. You asked previously that who might have
>>>>>> requested the anon mapping which is already present in there ? Would
>>>>>> not that be the same process itself ? I am bit confused.
>>>>> We are early in the ELF loading. If we are mapping over an existing
>>>>> mapping then we are effectivelly corrupting it. In other words exactly
>>>>> what this patch tries to prevent. I fail to see what would be a relevant
>>>>> anon mapping this early and why it would be colliding with elf
>>>>> segements.
>>>>>
>>>>>> Would it be
>>>>>> helpful to trap all the mmap() requests from any of the binaries
>>>>>> and see where we might have created that anon mapping ?
>>>>> Yeah, that is exactly what I was suggesting. Sorry for not being clear
>>>>> about that.
>>>>>
>>>> Tried to instrument just for the 'sed' binary and dont see any where
>>>> it actually requests the anon VMA which got hit when loading the ELF
>>>> section which is strange. All these requested flags here already has
>>>> MAP_FIXED_NOREPLACE (0x100000). Wondering from where the anon VMA
>>>> actually came from.
>>> Could you try to dump backtrace?
>> This is when it fails inside elf_map() function due to collision with
>> existing anon VMA mapping.
> This is not the interesting one. This is the ELF loader. And we know it
> fails. We are really interested in the one _who_ installs the original
> VMA. Because nothing should be really there.
> 

I tried to instrument mmap_region() for a single instance of 'sed'
binary and traced all it's VMA creation. But there is no trace when
that 'anon' VMA got created which suddenly shows up during subsequent
elf_map() call eventually failing it. Please note that the following
VMA was never created through call into map_region() in the process
which is strange.

=================================================================
[    9.076867] Details for VMA[3] c000001fce42b7c0
[    9.076925] vma c000001fce42b7c0 start 0000000010030000 end 0000000010040000
next c000001fce42b580 prev c000001fce42b880 mm c000001fce40fa00
prot 8000000000000104 anon_vma           (null) vm_ops           (null)
pgoff 1003 file           (null) private_data           (null)
flags: 0x100073(read|write|mayread|maywrite|mayexec|account)
=================================================================

VMA creation for 'sed' binary
=============================
[    9.071902] XXX: mm c000001fce40fa00 registered

[    9.071971] Total VMAs 2 on MM c000001fce40fa00
----
[    9.072010] Details for VMA[1] c000001fce42bdc0
[    9.072064] vma c000001fce42bdc0 start 0000000010000000 end 0000000010020000
next c000001fce42b580 prev           (null) mm c000001fce40fa00
prot 8000000000000105 anon_vma           (null) vm_ops c008000011ddca18
pgoff 0 file c000001fe2969a00 private_data           (null)
flags: 0x875(read|exec|mayread|maywrite|mayexec|denywrite)
----
[    9.072402] Details for VMA[2] c000001fce42b580
[    9.072469] vma c000001fce42b580 start 00007fffcafe0000 end 00007fffcb010000
next           (null) prev c000001fce42bdc0 mm c000001fce40fa00
prot 8000000000000104 anon_vma c000001fce4456f0 vm_ops           (null)
pgoff 1fffffffd file           (null) private_data           (null)
flags: 0x100173(read|write|mayread|maywrite|mayexec|growsdown|account)

[    9.072839] CPU: 48 PID: 7544 Comm: sed Not tainted 4.14.0-dirty #154
[    9.072928] Call Trace:
[    9.072952] [c000001fbef37840] [c000000000b17a00] dump_stack+0xb0/0xf0 (unreliable)
[    9.073021] [c000001fbef37880] [c0000000002dbc48] mmap_region+0x718/0x720
[    9.073097] [c000001fbef37970] [c0000000002dc034] do_mmap+0x3e4/0x480
[    9.073179] [c000001fbef379f0] [c0000000002a96c8] vm_mmap_pgoff+0xe8/0x120
[    9.073268] [c000001fbef37ac0] [c0000000003cf378] elf_map+0x98/0x270
[    9.073326] [c000001fbef37b60] [c0000000003d1258] load_elf_binary+0x6f8/0x158c
[    9.073416] [c000001fbef37c80] [c00000000035d320] search_binary_handler+0xd0/0x270
[    9.073510] [c000001fbef37d10] [c00000000035f278] do_execveat_common.isra.31+0x658/0x890
[    9.073599] [c000001fbef37df0] [c00000000035f8c0] SyS_execve+0x40/0x50
[    9.073673] [c000001fbef37e30] [c00000000000b220] system_call+0x58/0x6c


[    9.073749] Total VMAs 3 on MM c000001fce40fa00
----
[    9.073795] Details for VMA[1] c000001fce42bdc0
[    9.073847] vma c000001fce42bdc0 start 0000000010000000 end 0000000010020000
next c000001fce42b880 prev           (null) mm c000001fce40fa00
prot 8000000000000105 anon_vma           (null) vm_ops c008000011ddca18
pgoff 0 file c000001fe2969a00 private_data           (null)
flags: 0x875(read|exec|mayread|maywrite|mayexec|denywrite)
----
[    9.074170] Details for VMA[2] c000001fce42b880
[    9.074236] vma c000001fce42b880 start 0000000010020000 end 0000000010030000
next c000001fce42b580 prev c000001fce42bdc0 mm c000001fce40fa00
prot 8000000000000104 anon_vma           (null) vm_ops c008000011ddca18
pgoff 1 file c000001fe2969a00 private_data           (null)
flags: 0x100873(read|write|mayread|maywrite|mayexec|denywrite|account)
----
[    9.074612] Details for VMA[3] c000001fce42b580
[    9.074661] vma c000001fce42b580 start 00007fffcafe0000 end 00007fffcb010000
next           (null) prev c000001fce42b880 mm c000001fce40fa00
prot 8000000000000104 anon_vma c000001fce4456f0 vm_ops           (null)
pgoff 1fffffffd file           (null) private_data           (null)
flags: 0x100173(read|write|mayread|maywrite|mayexec|growsdown|account)

[    9.075038] CPU: 48 PID: 7544 Comm: sed Not tainted 4.14.0-dirty #154
[    9.075104] Call Trace:
[    9.075124] [c000001fbef37840] [c000000000b17a00] dump_stack+0xb0/0xf0 (unreliable)
[    9.075212] [c000001fbef37880] [c0000000002db824] mmap_region+0x2f4/0x720
[    9.075288] [c000001fbef37970] [c0000000002dc034] do_mmap+0x3e4/0x480
[    9.075358] [c000001fbef379f0] [c0000000002a96c8] vm_mmap_pgoff+0xe8/0x120
[    9.075432] [c000001fbef37ac0] [c0000000003cf378] elf_map+0x98/0x270
[    9.075490] [c000001fbef37b60] [c0000000003d1258] load_elf_binary+0x6f8/0x158c
[    9.075591] [c000001fbef37c80] [c00000000035d320] search_binary_handler+0xd0/0x270
[    9.075675] [c000001fbef37d10] [c00000000035f278] do_execveat_common.isra.31+0x658/0x890
[    9.075765] [c000001fbef37df0] [c00000000035f8c0] SyS_execve+0x40/0x50
[    9.075834] [c000001fbef37e30] [c00000000000b220] system_call+0x58/0x6c

When it fails
===============
[    9.075910] 7544 (sed): Uhuuh, elf segment at 0000000010030000 requested but the memory is mapped already

[    9.076010] Total VMAs 4 on MM c000001fce40fa00
----
[    9.076055] Details for VMA[1] c000001fce42bdc0
[    9.076103] vma c000001fce42bdc0 start 0000000010000000 end 0000000010020000
next c000001fce42b880 prev           (null) mm c000001fce40fa00
prot 8000000000000105 anon_vma           (null) vm_ops c008000011ddca18
pgoff 0 file c000001fe2969a00 private_data           (null)
flags: 0x875(read|exec|mayread|maywrite|mayexec|denywrite)
----
[    9.076461] Details for VMA[2] c000001fce42b880
[    9.076509] vma c000001fce42b880 start 0000000010020000 end 0000000010030000
next c000001fce42b7c0 prev c000001fce42bdc0 mm c000001fce40fa00
prot 8000000000000104 anon_vma           (null) vm_ops c008000011ddca18
pgoff 1 file c000001fe2969a00 private_data           (null)
flags: 0x100873(read|write|mayread|maywrite|mayexec|denywrite|account)
----
[    9.076867] Details for VMA[3] c000001fce42b7c0
[    9.076925] vma c000001fce42b7c0 start 0000000010030000 end 0000000010040000
next c000001fce42b580 prev c000001fce42b880 mm c000001fce40fa00
prot 8000000000000104 anon_vma           (null) vm_ops           (null)
pgoff 1003 file           (null) private_data           (null)
flags: 0x100073(read|write|mayread|maywrite|mayexec|account)
-----
[    9.077285] Details for VMA[4] c000001fce42b580
[    9.077335] vma c000001fce42b580 start 00007fffcafe0000 end 00007fffcb010000
next           (null) prev c000001fce42b7c0 mm c000001fce40fa00
prot 8000000000000104 anon_vma c000001fce4456f0 vm_ops           (null)
pgoff 1fffffffd file           (null) private_data           (null)
flags: 0x100173(read|write|mayread|maywrite|mayexec|growsdown|account)