Reproducible crash in PHP 8.4 with JIT and Excimer

[tstarling]

Description

• Download MediaWiki e.g. from https://releases.wikimedia.org/mediawiki/1.42/mediawiki-core-1.42.1.tar.gz
• cd mediawiki-1.42.1
• Install PHP 8.4 or git master with excimer and the extensions listed in composer.json
• Install MediaWiki e.g. with

php8.4 maintenance/run.php install --dbname=mw_installtest --dbserver=localhost --dbuser=user --dbpass=pass --pass=$(md5sum README.md) installtest Admin

Create the file phptest.php:

<?php
$excimer = new ExcimerProfiler;
$excimer->setPeriod( 0.001 );
$excimer->setEventType( EXCIMER_REAL );
$excimer->start();

require 'index.php';

Run the script repeatedly with the tracing JIT:

SCRIPT_NAME=index.php REMOTE_ADDR=1.2.3.4 /usr/lib/cgi-bin/php8.4 -T1000 -dextension=excimer.so -dopcache.jit=on phptest.php > /dev/null

It crashes with:

zend_mm_heap corrupted
Aborted (core dumped)

Building with AddressSanitizer, it always crashes in AutoLoader::find() due to an incorrect reference count on $prefix leading to it being freed while still in use.

In gdb, use set print thread-events off since Excimer is creating 1000 threads per second.

This is not an excimer bug. I'm pretty sure. Excimer is just a way to randomly set EG(vm_interrupt), which exercises some otherwise unusual exits in the JITed code of this function. It still crashes with the whole interrupt handler disabled:

diff --git a/excimer_timer.c b/excimer_timer.c
index 83bf42a..36e4289 100644
--- a/excimer_timer.c
+++ b/excimer_timer.c
@@ -239,6 +239,7 @@ static void excimer_timer_handle(union sigval sv)
 
 static void excimer_timer_interrupt(zend_execute_data *execute_data)
 {
+       return;
        zend_long id;
        zval *zp_count;
        HashTable *event_counts;

I mean, it is Excimer-related, and I as an Excimer maintainer am trying to fix it. But I'm getting deep into the JIT internals and that's probably where the bug is.

The bug is new in 8.4, I could not reproduce it in 8.3.

PHP Version

8.4.0alpha4

Operating System

Ubuntu 22.04

[cmb69]

The bug is new in 8.4, I could not reproduce it in 8.3.

Might be caused by the new IR JIT implementation.

[tstarling]

In slightly different conditions to the reproduction procedure above, the error always occurs with return address 0x48000d29, which is the zif_strrpos() call in TRACE-1$AutoLoader::find$181. Always that first trace out of hundreds.

The string's refcount is not off by one, it's garbage, like a billion, and yet the string has the right value in it.

AddressSanitizer shows a use after free, but the backtrace for the allocation is distant and random. Often it fails with an assertion while trying to print the backtrace.

[iluuu1994]

/cc @dstogov

[tstarling]

I think I've got it pretty well isolated.

I reduced the test code by making a tight loop of Autoloader::find() calls instead of running the whole of MediaWiki.

The bug does not seem to happen when opcache.jit_max_side_traces=0.

There are three relevant traces:

• TRACE-1: the root trace representing the while() at line 181
• TRACE-111: the if( isset() ) body at line 185
• TRACE-125: the if( is_file() ) at line 191

Code with line numbers for reference:

181:			while ( ( $pos = strrpos( $prefix, '\\' ) ) !== false ) {
182:				// Check to see if this namespace prefix is in the map
183:				$prefix = substr( $className, 0, $pos + 1 );
184:				if ( isset( self::$psr4Namespaces[$prefix] ) ) {
185:					$relativeClass = substr( $className, $pos + 1 );
186:					// Build the expected filename, and see if it exists
187:					$file = self::$psr4Namespaces[$prefix] .
188:						'/' .
189:						strtr( $relativeClass, '\\', '/' ) .
190:						'.php';
191:					if ( is_file( $file ) ) {
192:						$filename = $file;
193:						break;
194:					}
195:				}
196:
197:				// Remove trailing separator for next iteration
198:				$prefix = rtrim( $prefix, '\\' );
199:			}

The bug occurs when EG(vm_interrupt) is set leading to TRACE-125 exit 3. A debug message is not emitted in that case, but I fixed that so that we see:

     TRACE 125 exit 3 AutoLoader::find() /srv/mw/core/includes/AutoLoader.php:198

The interrupt handler stub is then called, but the opline is wrong. It returns to the VM, but execution resumes at the ZEND_ASSIGN op on line 198, not at the rtrim() call. Both operands of the ZEND_ASSIGN at this point refer to the same string ($prefix). The ZEND_ASSIGN handler decrements the reference count of $prefix, causing it to be freed. Then the loop continues, re-entering TRACE-1 and crashing in strrpos().

[tstarling]

I think the zend_jit_check_timeout() call in zend_jit_trace_link_to_root() is at fault. Commenting it out seems to fix the issue. It passes NULL for opline but presumably should pass whatever the right answer is.

[dstogov]

@tstarling Can you please check, if the following patch fixes the problem.

diff --git a/ext/opcache/jit/zend_jit_ir.c b/ext/opcache/jit/zend_jit_ir.c
index bb0caf477e5..b31c66016dd 100644
--- a/ext/opcache/jit/zend_jit_ir.c
+++ b/ext/opcache/jit/zend_jit_ir.c
@@ -16729,7 +16729,7 @@ static int zend_jit_trace_link_to_root(zend_jit_ctx *jit, zend_jit_trace_info *t
 	link_addr = (const void*)((const char*)t->code_start + zend_jit_trace_prologue_size);
 
 	if (timeout_exit_addr) {
-		zend_jit_check_timeout(jit, NULL, timeout_exit_addr);
+		zend_jit_check_timeout(jit, t->opline, timeout_exit_addr);
 	}
 	ir_IJMP(ir_CONST_ADDR(link_addr));

[dstogov]

No, my patch is wrong. The opline passed to zend_jit_check_timeout() doesn't matter when exit_addr is passed.

The target opline should be set by deoptimization process.
The corresponding deoptimization info is created here https://github.com/php/php-src/blob/master/ext/opcache/jit/zend_jit_trace.c#L7162 and these lines exactly the same in PHP_8_3.

[dstogov]

TRACE 125 exit 3 AutoLoader::find() /srv/mw/core/includes/AutoLoader.php:198

The interrupt handler stub is then called, but the opline is wrong. It returns to the VM, but execution resumes at the ZEND_ASSIGN op on line 198, not at the rtrim() call. Both operands of the ZEND_ASSIGN at this point refer to the same string ($prefix). The ZEND_ASSIGN handler decrements the reference count of $prefix, causing it to be freed. Then the loop continues, re-entering TRACE-1 and crashing in strrpos().

Can you check the deoptimization info for TRACE-125 exit 3 is correct? (it should be printed after TRACE-125 disassemble with opcache.jit_debug=0x1ff001) e.g exit_3: XXXX/... where XXX is the target opline number. It should be the same as the first opline of the root trace.

[dstogov]

@bwoebi @morrisonlevi may be you have any ideas about the reason of failure.

[tstarling]

Can you check the deoptimization info for TRACE-125 exit 3 is correct?

It's hard to say what is correct. The exit points to the assignment op, but maybe the assignment was already done by the JIT.

Today I'm actually following the reproduction procedure instead of using my main MW test install. So some things have moved around a bit. The source line numbers have changed by 2 compared to what I previously pasted. You can see the source file at https://github.com/wikimedia/mediawiki/blob/1.42.1/includes/AutoLoader.php . The trace numbers and exit numbers have changed.

I'm using this PHP: https://github.com/tstarling/php-src/tree/autoload-debug . It is git master from last week, with a few patches, most notably a patch to show a JIT exit message even when vm_interrupt is set.

Today the crash usually happens at trace 26 exit 9.

The op array dump:

AutoLoader::find:
     ; (lines=67, args=1, vars=8, tmps=4)
     ; (after optimizer)
     ; /var/tmp/mediawiki-1.42.1/includes/AutoLoader.php:165-212
0000 CV0($className) = RECV 1
0001 BIND_GLOBAL CV1($wgAutoloadLocalClasses) string("wgAutoloadLocalClasses")
0002 BIND_GLOBAL CV2($wgAutoloadClasses) string("wgAutoloadClasses")
0003 T9 = FETCH_DIM_IS CV1($wgAutoloadLocalClasses) CV0($className)
0004 T8 = COALESCE T9 0013
0005 T9 = FETCH_STATIC_PROP_IS string("classFiles") (self) (exception)
0006 T10 = FETCH_DIM_IS T9 CV0($className)
0007 T9 = COALESCE T10 0012
0008 T11 = FETCH_DIM_IS CV2($wgAutoloadClasses) CV0($className)
0009 T10 = COALESCE T11 0011
0010 T10 = QM_ASSIGN bool(false)
0011 T9 = QM_ASSIGN T10
0012 T8 = QM_ASSIGN T9
0013 CV3($filename) = QM_ASSIGN T8
0014 JMPNZ CV3($filename) 0057
0015 T9 = FRAMELESS_ICALL_2(strpos) CV0($className) string("\\")
0016 T8 = TYPE_CHECK TYPE [null, true, long, double, string, array, object, resource] T9
0017 JMPZ T8 0055
0018 CV4($prefix) = QM_ASSIGN CV0($className)
0019 JMP 0049
0020 T9 = ADD CV5($pos) int(1)
0021 T8 = FRAMELESS_ICALL_3(substr) CV0($className) int(0)
0022 OP_DATA T9
0023 ASSIGN CV4($prefix) T8
0024 T9 = FETCH_STATIC_PROP_IS string("psr4Namespaces") (self) (exception)
0025 T8 = ISSET_ISEMPTY_DIM_OBJ (isset) T9 CV4($prefix)
0026 JMPZ T8 0044
0027 T9 = ADD CV5($pos) int(1)
0028 T8 = FRAMELESS_ICALL_2(substr) CV0($className) T9
0029 ASSIGN CV6($relativeClass) T8
0030 T8 = FETCH_STATIC_PROP_R string("psr4Namespaces") (self) (exception)
0031 T9 = FETCH_DIM_R T8 CV4($prefix)
0032 T8 = CONCAT T9 string("/")
0033 T10 = FRAMELESS_ICALL_3(strtr) CV6($relativeClass) string("\\")
0034 OP_DATA string("/")
0035 T9 = FAST_CONCAT T8 T10
0036 T8 = FAST_CONCAT T9 string(".php")
0037 ASSIGN CV7($file) T8
0038 INIT_FCALL 1 96 string("is_file")
0039 SEND_VAR CV7($file) 1
0040 V8 = DO_ICALL
0041 JMPZ V8 0044
0042 ASSIGN CV3($filename) CV7($file)
0043 JMP 0055
0044 INIT_FCALL 2 112 string("rtrim")
0045 SEND_VAR CV4($prefix) 1
0046 SEND_VAL string("\\") 2
0047 V8 = DO_ICALL
0048 ASSIGN CV4($prefix) V8
0049 INIT_FCALL 2 112 string("strrpos")
0050 SEND_VAR CV4($prefix) 1
0051 SEND_VAL string("\\") 2
0052 CV5($pos) = DO_ICALL
0053 T8 = TYPE_CHECK TYPE [null, true, long, double, string, array, object, resource] CV5($pos)
0054 JMPNZ T8 0020
0055 JMPNZ CV3($filename) 0057
0056 RETURN null
0057 T9 = FETCH_DIM_R CV3($filename) int(0)
0058 T8 = IS_NOT_IDENTICAL T9 string("/")
0059 JMPZ T8 0065
0060 T9 = FETCH_DIM_R CV3($filename) int(1)
0061 T8 = IS_NOT_IDENTICAL T9 string(":")
0062 JMPZ T8 0065
0063 T8 = CONCAT string("/var/tmp/mediawiki-1.42.1/includes/../") CV3($filename)
0064 ASSIGN CV3($filename) T8
0065 VERIFY_RETURN_TYPE CV3($filename)
0066 RETURN CV3($filename)
LIVE RANGES:
     8: 0022 - 0023 (tmp/var)
     8: 0033 - 0035 (tmp/var)
     10: 0034 - 0035 (tmp/var)

The side trace:

---- TRACE 26 start (side trace 12/6) AutoLoader::find() /var/tmp/mediawiki-1.42.1/includes/AutoLoader.php:183
0027 T9 = ADD CV5($pos) int(1) ; op1(int)
0028 T8 = FRAMELESS_ICALL_2(substr) CV0($className) T9 ; op1(string) op2(int)
0029 ASSIGN CV6($relativeClass) T8 ; op1(undef) op2(string)
0030 T8 = FETCH_STATIC_PROP_R string("psr4Namespaces") (self) (exception)
0031 T9 = FETCH_DIM_R T8 CV4($prefix) ; op1(array) op2(string) val(string)
0032 T8 = CONCAT T9 string("/") ; op1(string)
0033 T10 = FRAMELESS_ICALL_3(strtr) CV6($relativeClass) string("\\") ; op1(string)
0034 ;OP_DATA string("/")
0035 T9 = FAST_CONCAT T8 T10 ; op1(string) op2(string)
0036 T8 = FAST_CONCAT T9 string(".php") ; op1(string)
0037 ASSIGN CV7($file) T8 ; op1(undef) op2(string)
0038 INIT_FCALL 1 96 string("is_file")
     >init is_file
0039 SEND_VAR CV7($file) 1 ; op1(string)
0040 V8 = DO_ICALL
     >call is_file
0041 JMPZ V8 0044 ; op1(bool)
0044 INIT_FCALL 2 112 string("rtrim")
     >init rtrim
0045 SEND_VAR CV4($prefix) 1 ; op1(string)
0046 SEND_VAL string("\\") 2
0047 V8 = DO_ICALL
     >call rtrim
0048 ASSIGN CV4($prefix) V8 ; op1(string) op2(string)
---- TRACE 26 stop (link to 12)
---- TRACE 26 TSSA start (side trace 12/6) AutoLoader::find() /var/tmp/mediawiki-1.42.1/includes/AutoLoader.php:183
     ;#0.CV0($className) [rc1, rcn, any]
     ;#4.CV4($prefix) [rc1, rcn, string]
     ;#5.CV5($pos) [long]
     ;#6.CV6($relativeClass) NOVAL [undef, rc1, rcn, string]
     ;#7.CV7($file) NOVAL [undef, rc1, rcn, string]
0027 #12.T9 [long, double] = ADD #5.CV5($pos) [long] int(1) ; op1(int)
0028 #14.T8 [rc1, rcn, string] = FRAMELESS_ICALL_2(substr) #0.CV0($className) [rc1, rcn, any] -> #13.CV0($className) NOVAL [rc1, rcn, any] #12.T9 [long, double] ; op1(string) op2(int)
0029 ASSIGN #6.CV6($relativeClass) NOVAL [undef, rc1, rcn, string] -> #15.CV6($relativeClass) [rc1, rcn, string] #14.T8 [rc1, rcn, string] ; op1(undef) op2(string)
0030 #16.T8 [!rcn, array of [any, ref]] = FETCH_STATIC_PROP_R string("psr4Namespaces") (self) (exception)
0031 #17.T9 [!rcn, string] = FETCH_DIM_R #16.T8 [!rcn, array of [any, ref]] #4.CV4($prefix) [rc1, rcn, string] ; op1(array) op2(string) val(string)
0032 #18.T8 [rc1, rcn, string] = CONCAT #17.T9 [!rcn, string] string("/") ; op1(string)
0033 #20.T10 [rc1, rcn, string] = FRAMELESS_ICALL_3(strtr) #15.CV6($relativeClass) [rc1, rcn, string] -> #19.CV6($relativeClass) NOVAL [rc1, rcn, string] string("\\") ; op1(string)
0034 ;OP_DATA string("/")
0035 #21.T9 [rc1, rcn, string] = FAST_CONCAT #18.T8 [rc1, rcn, string] #20.T10 [rc1, rcn, string] ; op1(string) op2(string)
0036 #22.T8 [rc1, rcn, string] = FAST_CONCAT #21.T9 [rc1, rcn, string] string(".php") ; op1(string)
0037 ASSIGN #7.CV7($file) NOVAL [undef, rc1, rcn, string] -> #23.CV7($file) [rc1, rcn, string] #22.T8 [rc1, rcn, string] ; op1(undef) op2(string)
0038 INIT_FCALL 1 96 string("is_file")
     >init is_file
0039 SEND_VAR #23.CV7($file) [rc1, rcn, string] -> #24.CV7($file) [rc1, rcn, string] 1 ; op1(string)
0040 #25.V8 [!false] = DO_ICALL
     >call is_file
0041 JMPZ #25.V8 [!false] 0044 ; op1(bool)
0044 INIT_FCALL 2 112 string("rtrim")
     >init rtrim
0045 SEND_VAR #4.CV4($prefix) [rc1, rcn, string] -> #26.CV4($prefix) NOVAL [rc1, rcn, string] 1 ; op1(string)
0046 SEND_VAL string("\\") 2
0047 #27.V8 [rc1, rcn, string] = DO_ICALL
     >call rtrim
0048 ASSIGN #26.CV4($prefix) NOVAL [rc1, rcn, string] -> #28.CV4($prefix) [rc1, rcn, string] #27.V8 [rc1, rcn, string] ; op1(string) op2(string)
---- TRACE 26 TSSA stop (link to 12)

The disassembly from the rtrim call to exit 9, annotated with my tracing observations, especially CV4($prefix) refcount:

    48004c8e:   movabsq $zif_rtrim, %rax
    48004c98:   callq *%rax
    48004c9a:   movabsq $EG(current_execute_data), %rax
    48004ca4:   movq %r14, (%rax)
    48004ca7:   cmpb $0, 0x59(%r15)
    48004cac:   je .L12
    48004cae:   movq 0x50(%r15), %rdi
    48004cb2:   subl $1, (%rdi)                            # CV4 refcount 2->1
    48004cb5:   jne .L12
    48004cb7:   movq $0x408ec860, (%r14)
    48004cbe:   movabsq $rc_dtor_func, %rax
    48004cc8:   callq *%rax
.L12:
    48004cca:   movabsq $EG(vm_stack_top), %rax
    48004cd4:   movq %r15, (%rax)
    48004cd7:   movabsq $EG(exception), %rax
    48004ce1:   movq (%rax), %rax
    48004ce4:   testq %rax, %rax
    48004ce7:   jne JIT$$icall_throw
    48004ced:   movabsq $EG(vm_interrupt), %rax
    48004cf7:   movb (%rax), %al
    48004cfa:   testb %al, %al
    48004cfd:   jne jit$$trace_exit_8                      # not taken
    48004d03:   cmpb $0, 0x99(%r14)
    48004d0b:   jne .L14                                   # taken
    48004d0d:   movq 0xd0(%r14), %rax
    48004d14:   movq %rax, 0x90(%r14)
    48004d1b:   movl 0xd8(%r14), %eax
    48004d22:   movl %eax, 0x98(%r14)
.L13:
    48004d29:   movabsq $EG(vm_interrupt), %rax
    48004d33:   movb (%rax), %al
    48004d36:   testb %al, %al
    48004d39:   je TRACE-12$AutoLoader::find$179+0x8
    48004d3f:   jmp jit$$trace_exit_9
.L14:
    48004d44:   movq 0x90(%r14), %rdi
    48004d4b:   movq 0xd0(%r14), %rax
    48004d52:   movq %rax, 0x90(%r14)
    48004d59:   movl 0xd8(%r14), %eax
    48004d60:   movl %eax, 0x98(%r14)
    48004d67:   subl $1, (%rdi)                            # CV4 refcount 1->0
    48004d6a:   jne .L13                                   # not taken
    48004d6c:   movq $0x408ec880, (%r14)
    48004d73:   movabsq $rc_dtor_func, %rax
    48004d7d:   callq *%rax                                # CV4 refcount 0->asan garbage
    48004d7f:   jmp .L13

So maybe the stack is corrupted before the exit is even taken.