Bug #72623 [NEW]: P7.1.0 Opcache multibyte get_mmap_base_file() results in 500 error (Apache)

From: caaguado at xcentra dot com Operating system: Windows PHP version: 7.1.0alpha3 Package: opcache Bug Type: Bug Bug description:P7.1.0 Opcache multibyte get_mmap_base_file() results in 500 error (Apache) Description: ------------ The new PHP 7.1.0 multibyte implementation of /ext/opcache/shared_alloc_win32.c get_mmap_base_file() function results in Opcache's "Fatal Error Unable to write base address", causing Apache's mod_cgi module to fail with an "End of script output before headers: php-cgi.exe" error, ultimately leading to a 500 Internal Server Error being served to the browser. Problem reproduced in Apache 2.4.23 and Apache 2.4.20 (Win32, VC14, Apache Lounge binaries, see http://www.apachelounge.com/download/) and Apache 1.3.41 (Win32, ASF legacy binaries). Problem NON EXISTING on Nginx 1.11.x for Win32 (PHP 7.1.0alpha3 runs smoothly). I have not tested the problem in Microsoft ISS. Apache 2.4.23 error log with LogLevel directive set to "trace8" in Apache's configuration file (maximum level of tracing detail): [Mon Jul 18 08:44:56.513307 2016] [unique_id:info] [pid 2628:tid 184] AH01566: using ip addr 192.168.56.1 [Mon Jul 18 08:44:57.074908 2016] [core:trace3] [pid 2628:tid 184] core.c(3269): Setting LogLevel for all modules to trace8 [Mon Jul 18 08:44:57.106108 2016] [unique_id:info] [pid 2628:tid 184] AH01566: using ip addr 192.168.56.1 [Mon Jul 18 08:44:58.010910 2016] [mpm_winnt:notice] [pid 2628:tid 184] AH00455: Apache/2.4.23 (Win32) configured -- resuming normal operations [Mon Jul 18 08:44:58.010910 2016] [mpm_winnt:notice] [pid 2628:tid 184] AH00456: Apache Lounge VC14 Server built: Jul 1 2016 11:09:37 [Mon Jul 18 08:44:58.010910 2016] [core:notice] [pid 2628:tid 184] AH00094: Command line: 'S:\\xtack\\bin\\a24\\bin\\httpd.exe -d S:/xtack/bin/a24 -f S:\\xtack\\cfg\\apache24_port.conf' [Mon Jul 18 08:44:58.010910 2016] [core:debug] [pid 2628:tid 184] log.c(1543): AH02639: Using SO_REUSEPORT: no (0) [Mon Jul 18 08:44:58.135710 2016] [mpm_winnt:notice] [pid 2628:tid 184] AH00418: Parent: Created child process 2728 [Mon Jul 18 08:44:58.135710 2016] [mpm_winnt:debug] [pid 2628:tid 184] mpm_winnt.c(429): AH00402: Parent: Sent the scoreboard to the child [Mon Jul 18 08:44:59.040512 2016] [core:trace3] [pid 2728:tid 200] core.c(3269): Setting LogLevel for all modules to trace8 [Mon Jul 18 08:44:59.071712 2016] [unique_id:info] [pid 2728:tid 200] AH01566: using ip addr 192.168.56.1 [Mon Jul 18 08:45:00.163714 2016] [core:trace3] [pid 2728:tid 200] core.c(3269): Setting LogLevel for all modules to trace8 [Mon Jul 18 08:45:00.241714 2016] [unique_id:info] [pid 2728:tid 200] AH01566: using ip addr 192.168.56.1 [Mon Jul 18 08:45:01.006115 2016] [mpm_winnt:debug] [pid 2728:tid 200] mpm_winnt.c(1718): AH00453: Child process is running [Mon Jul 18 08:45:01.006115 2016] [mpm_winnt:debug] [pid 2728:tid 200] mpm_winnt.c(343): AH00391: Child: Retrieved our scoreboard from the parent. [Mon Jul 18 08:45:01.006115 2016] [mpm_winnt:debug] [pid 2728:tid 200] mpm_winnt.c(465): AH00403: Child: Waiting for data for listening socket 0.0.0.0:80 [Mon Jul 18 08:45:01.006115 2016] [mpm_winnt:debug] [pid 2628:tid 184] mpm_winnt.c(512): AH00408: Parent: Duplicating socket 176 (0.0.0.0:80) and sending it to child process 2728 [Mon Jul 18 08:45:01.006115 2016] [mpm_winnt:debug] [pid 2628:tid 184] mpm_winnt.c(512): AH00408: Parent: Duplicating socket 168 ([::]:80) and sending it to child process 2728 [Mon Jul 18 08:45:01.006115 2016] [mpm_winnt:debug] [pid 2628:tid 184] mpm_winnt.c(531): AH00411: Parent: Sent 2 listeners to child 2728 [Mon Jul 18 08:45:01.006115 2016] [core:trace4] [pid 2628:tid 184] mpm_common.c(531): mpm child 2728 (gen 0/slot 0) started [Mon Jul 18 08:45:01.006115 2016] [mpm_winnt:debug] [pid 2728:tid 200] mpm_winnt.c(465): AH00403: Child: Waiting for data for listening socket [::]:80 [Mon Jul 18 08:45:01.006115 2016] [mpm_winnt:debug] [pid 2728:tid 200] mpm_winnt.c(490): AH00407: Child: retrieved 2 listeners from parent [Mon Jul 18 08:45:01.006115 2016] [mpm_winnt:debug] [pid 2728:tid 200] child.c(1020): AH00352: Child: Acquired the start mutex. [Mon Jul 18 08:45:01.006115 2016] [mpm_winnt:notice] [pid 2728:tid 200] AH00354: Child: Starting 150 worker threads. [Mon Jul 18 08:45:01.052915 2016] [mpm_winnt:debug] [pid 2728:tid 1684] child.c(399): AH00334: Child: Accept thread listening on 0.0.0.0:80 using AcceptFilter data [Mon Jul 18 08:45:01.052915 2016] [mpm_winnt:debug] [pid 2728:tid 1700] child.c(399): AH00334: Child: Accept thread listening on [::]:80 using AcceptFilter data [Mon Jul 18 08:45:06.295525 2016] [core:trace5] [pid 2728:tid 1672] protocol.c(614): [client 127.0.0.1:49302] Request received from client: GET /docs/phpinfo.php HTTP/1.1 [Mon Jul 18 08:45:06.295525 2016] [http:trace4] [pid 2728:tid 1672] http_request.c(393): [client 127.0.0.1:49302] Headers received from client: [Mon Jul 18 08:45:06.295525 2016] [http:trace4] [pid 2728:tid 1672] http_request.c(396): [client 127.0.0.1:49302] Host: 127.0.0.1 [Mon Jul 18 08:45:06.295525 2016] [http:trace4] [pid 2728:tid 1672] http_request.c(396): [client 127.0.0.1:49302] User-Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:47.0) Gecko/20100101 Firefox/47.0 [Mon Jul 18 08:45:06.295525 2016] [http:trace4] [pid 2728:tid 1672] http_request.c(396): [client 127.0.0.1:49302] Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 [Mon Jul 18 08:45:06.295525 2016] [http:trace4] [pid 2728:tid 1672] http_request.c(396): [client 127.0.0.1:49302] Accept-Language: en-US,en;q=0.8,es-ES;q=0.5,es;q=0.3 [Mon Jul 18 08:45:06.295525 2016] [http:trace4] [pid 2728:tid 1672] http_request.c(396): [client 127.0.0.1:49302] Accept-Encoding: gzip, deflate [Mon Jul 18 08:45:06.295525 2016] [http:trace4] [pid 2728:tid 1672] http_request.c(396): [client 127.0.0.1:49302] DNT: 1 [Mon Jul 18 08:45:06.295525 2016] [http:trace4] [pid 2728:tid 1672] http_request.c(396): [client 127.0.0.1:49302] Connection: keep-alive [Mon Jul 18 08:45:06.295525 2016] [authz_core:debug] [pid 2728:tid 1672] mod_authz_core.c(834): [client 127.0.0.1:49302] AH01628: authorization result: granted (no directives) [Mon Jul 18 08:45:06.295525 2016] [core:trace3] [pid 2728:tid 1672] request.c(291): [client 127.0.0.1:49302] request authorized without authentication by access_checker_ex hook: /docs/phpinfo.php [Mon Jul 18 08:45:06.295525 2016] [authz_core:debug] [pid 2728:tid 1672] mod_authz_core.c(834): [client 127.0.0.1:49302] AH01628: authorization result: granted (no directives) [Mon Jul 18 08:45:06.295525 2016] [core:trace3] [pid 2728:tid 1672] request.c(291): [client 127.0.0.1:49302] request authorized without authentication by access_checker_ex hook: /p71/php-cgi.exe/docs/phpinfo.php [Mon Jul 18 08:45:06.295525 2016] [authz_core:debug] [pid 2728:tid 1672] mod_authz_core.c(834): [client 127.0.0.1:49302] AH01628: authorization result: granted (no directives) [Mon Jul 18 08:45:06.295525 2016] [core:trace3] [pid 2728:tid 1672] request.c(291): [client 127.0.0.1:49302] request authorized without authentication by access_checker_ex hook: /docs/phpinfo.php [Mon Jul 18 08:45:08.869529 2016] [cgi:error] [pid 2728:tid 1672] [client 127.0.0.1:49302] End of script output before headers: php-cgi.exe [Mon Jul 18 08:45:08.869529 2016] [http:trace3] [pid 2728:tid 1672] http_filters.c(1003): [client 127.0.0.1:49302] Response sent with status 500, headers: [Mon Jul 18 08:45:08.869529 2016] [http:trace5] [pid 2728:tid 1672] http_filters.c(1012): [client 127.0.0.1:49302] Date: Mon, 18 Jul 2016 06:45:06 GMT [Mon Jul 18 08:45:08.869529 2016] [http:trace5] [pid 2728:tid 1672] http_filters.c(1015): [client 127.0.0.1:49302] Server: Apache/2.4.23 (Win32) [Mon Jul 18 08:45:08.869529 2016] [http:trace4] [pid 2728:tid 1672] http_filters.c(833): [client 127.0.0.1:49302] Content-Length: 530 [Mon Jul 18 08:45:08.869529 2016] [http:trace4] [pid 2728:tid 1672] http_filters.c(833): [client 127.0.0.1:49302] Connection: close [Mon Jul 18 08:45:08.869529 2016] [http:trace4] [pid 2728:tid 1672] http_filters.c(833): [client 127.0.0.1:49302] Content-Type: text/html; charset=iso-8859-1 [Mon Jul 18 08:45:08.869529 2016] [core:trace6] [pid 2728:tid 1672] core_filters.c(523): [client 127.0.0.1:49302] core_output_filter: flushing because of FLUSH bucket [Mon Jul 18 08:45:08.916329 2016] [core:trace6] [pid 2728:tid 1672] core_filters.c(523): [client 127.0.0.1:49302] core_output_filter: flushing because of FLUSH bucket [Mon Jul 18 08:45:14.033138 2016] [core:trace6] [pid 2728:tid 1672] core_filters.c(523): [client 127.0.0.1:49303] core_output_filter: flushing because of FLUSH bucket Simultaneously, this creates the following two error entries for PHP Opcode: Mon Jul 18 08:45:08 2016 (2492): Warning C:\windows\\ZendOPcache.MemoryBase@<USERNAME>@402356d382908b6a81756e2b77648ded Mon Jul 18 08:45:08 2016 (2492): Fatal Error Unable to write base address <USERNAME> means the current user logged in in Windows. The problem is not depending on specific machines nor Windows versions. I have reproduced it in four different machines, running four different versions of MS Windows: - Hewlett-Packard HP EliteBook 8460p system with 2x Intel Core i5-2540M CPU @ 2.60GHz core(s), 8 GB RAM and Microsoft Windows 7 Enterprise Multiprocessor Free SP1 64 bits version 6.1.7601. - Apple Inc. MacBookAir6 2 system with 2x Intel Core i7-4650U CPU @ 1.70GHz core(s), 8 GB RAM and Microsoft Windows 8.1 Pro Multiprocessor Free SP0 64 bits version 6.3.9600. - HP-Pavilion GU620AA-ABE m9080.es system with 4x Intel Core2 Quad CPU Q6600 @ 2.40GHz core(s), 7 GB RAM and Microsoft Windows 10 Pro Multiprocessor Free SP0 64 bits version 10.0.10586. - VirtualBox VIRTUAL MACHINE: innotek GmbH VirtualBox system with 1x Intel Core i5-2540M CPU @ 2.60GHz core(s), 2 GB RAM and Microsoft Windows 10 Pro Multiprocessor Free SP0 64 bits version 10.0.10240. The problem doesn't depend either on the system's "TEMP" nor "TMP" setting: Problem observed with (several tests): TEMP=C:\Users\<USERNAME>\AppData\Local\Temp TMP=C:\Users\<USERNAME>\AppData\Local\Temp and: TEMP=C:\Temp TMP=C:\Temp The problem IS NOT either depending on the Apache stack and configuration used, as it is exactly the same one I use with PHP 7.0.8, which is completely problem-free. I have even replaced the PHP 7.0.8 subdirectory with PHP 7.1.0alpha3 binaries to discard eventual Apache and PHP configuration issues and the problem also appears (that is, it ONLY seems to depend on PHP, and nothing else). Common FAULTYING code: ====================== if (mapping_base == NULL) { zend_shared_alloc_unlock_win32(); zend_win_error_message(ACCEL_LOG_FATAL, "Unable to create view for file mapping", err); *error_in = "MapViewOfFile"; return ALLOC_FAILURE; } else { char *mmap_base_file = get_mmap_base_file(); FILE *fp = fopen(mmap_base_file, "w"); <=========================================== **** err = GetLastError(); if (!fp) { zend_shared_alloc_unlock_win32(); zend_win_error_message(ACCEL_LOG_WARNING, mmap_base_file, err); zend_win_error_message(ACCEL_LOG_FATAL, "Unable to write base address", err); return ALLOC_FAILURE; } fprintf(fp, "%p\n", mapping_base); fclose(fp); } 7.1.0alpha3 implementation: =========================== #define ACCEL_FILEMAP_BASE "ZendOPcache.MemoryBase" static char *get_mmap_base_file(void) { static char windir[MAXPATHLEN+UNLEN + 3 + sizeof("\\\\@") + 1 + 32]; char *uname; int l; uname = php_win32_get_username(); if (!uname) { return NULL; } GetTempPath(MAXPATHLEN, windir); l = strlen(windir); snprintf(windir + l, sizeof(windir) - l - 1, "\\%s@%s@%.32s", ACCEL_FILEMAP_BASE, uname, ZCG(system_id)); free(uname); return windir; } 7.0.8 implementation: ===================== #define ACCEL_FILEMAP_BASE "ZendOPcache.MemoryBase" static char *get_mmap_base_file(void) { static char windir[MAXPATHLEN+UNLEN + 3 + sizeof("\\\\@") + 1 + 32]; char uname[UNLEN + 1]; DWORD unsize = UNLEN; int l; GetTempPath(MAXPATHLEN, windir); GetUserName(uname, &unsize); l = strlen(windir); snprintf(windir + l, sizeof(windir) - l - 1, "\\%s@%s@%.32s", ACCEL_FILEMAP_BASE, uname, ZCG(system_id)); return windir; } Function GetLastError() doesn't provide any last-error code (see https://msdn.microsoft.com/en-us/library/windows/desktop/ms679360(v=vs.85).aspx). The main difference in the code is that in 7.1.0alpha3: uname = php_win32_get_username(); Looking at the nested definition of php_win32_get_username(, it seems to be a PHP-specific wide character implementation. In 7.0.8 uname is determined via: GetUserName(uname, &unsize); Zend Engine is configured to detect Unicode both in 7.1.0alpha3 and 7.0.8 in /Zend/zend.c: STD_ZEND_INI_BOOLEAN("zend.detect_unicode", "1", ZEND_INI_ALL, OnUpdateBool, detect_unicode, zend_compiler_globals, compiler_globals) I also see that when running PHP 7.1.0alpha3 with Nginx 1.11.2, that phpinfo() reports that mbstring's Multibyte Support is enabled: Zend Multibyte Support provided by mbstring (...) Multibyte Support enabled Multibyte string engine libmbfl HTTP input encoding translation disabled libmbfl version 1.3.2 oniguruma version 5.9.6 I also see exactly the same configuration with Nginx 1.11.2 for PHP 7.0.8: Zend Multibyte Support provided by mbstring (...) Multibyte Support enabled Multibyte string engine libmbfl HTTP input encoding translation disabled libmbfl version 1.3.2 oniguruma version 5.9.6 The problem could be related to the fact that in order to support MultiByte Character Sets (MBCS) or Unicode, functions _snprintf (MBCS) or _snwprintf (Unicode) would need to be used: instead of function snprintf; See https://msdn.microsoft.com/en-us/library/2ts7cx93.aspx, which mentions that "Beginning with the UCRT in Visual Studio 2015 and Windows 10, snprintf is no longer identical to _snprintf. The snprintf function behavior is now C99 standard compliant." At the same time, looking at https://en.wikipedia.org/wiki/C99, it is said that "Future work: Since ratification of the 1999 C standard, the standards working group prepared technical reports specifying improved support for embedded processing, additional character data types (Unicode support)", implying (in my understanding) that function snprintf() DOES NOT support Unicode. It could also maybe be related to the fact that different types are used for variable uname (char * in 7.1.0alpha3 versus char[] in 7.0.8). See http://stackoverflow.com/questions/10186765/char-array-vs-char-pointer-in-c). Side issue: The code to generate the mmap_base_file full path within a temporary directory isn't optimal/robust, as at the moment the file is created within Windows' installation directory (usually C:\WINDOWS): snprintf(windir + l, sizeof(windir) - l - 1, "\\%s@%s@%.32s", ACCEL_FILEMAP_BASE, uname, ZCG(system_id)); The part causing the file to be created within Windows' installation directory is "\\%s@%s@%.32s". This should be better corrected, as very frequently, writting files to Windows' installation directory is not allowed by the OS. Test script: --------------- Nothing special is required; just fire Apache and PHP and head the browser to a simple PHP file only containing a call to phpinfo(); The error appears immediately. I can try whatever tests required in my own environment, which is already prepared for it. Expected result: ---------------- Fix this regression, in order to be able to run PHP 7.1.0(alpha/beta X) with Apache on Windows, the same way as with PHP 7.0.8. Actual result: -------------- See problem description body for both Apache and PHP error traces. -- Edit bug report at https://bugs.php.net/bug.php?id=72623&edit=1 -- Try a snapshot (PHP 5.4): https://bugs.php.net/fix.php?id=72623&r=trysnapshot54 Try a snapshot (PHP 5.5): https://bugs.php.net/fix.php?id=72623&r=trysnapshot55 Try a snapshot (trunk): https://bugs.php.net/fix.php?id=72623&r=trysnapshottrunk Fixed in SVN: https://bugs.php.net/fix.php?id=72623&r=fixed Fixed in release: https://bugs.php.net/fix.php?id=72623&r=alreadyfixed Need backtrace: https://bugs.php.net/fix.php?id=72623&r=needtrace Need Reproduce Script: https://bugs.php.net/fix.php?id=72623&r=needscript Try newer version: https://bugs.php.net/fix.php?id=72623&r=oldversion Not developer issue: https://bugs.php.net/fix.php?id=72623&r=support Expected behavior: https://bugs.php.net/fix.php?id=72623&r=notwrong Not enough info: https://bugs.php.net/fix.php?id=72623&r=notenoughinfo Submitted twice: https://bugs.php.net/fix.php?id=72623&r=submittedtwice register_globals: https://bugs.php.net/fix.php?id=72623&r=globals PHP 4 support discontinued: https://bugs.php.net/fix.php?id=72623&r=php4 Daylight Savings: https://bugs.php.net/fix.php?id=72623&r=dst IIS Stability: https://bugs.php.net/fix.php?id=72623&r=isapi Install GNU Sed: https://bugs.php.net/fix.php?id=72623&r=gnused Floating point limitations: https://bugs.php.net/fix.php?id=72623&r=float No Zend Extensions: https://bugs.php.net/fix.php?id=72623&r=nozend MySQL Configuration Error: https://bugs.php.net/fix.php?id=72623&r=mysqlcfg