Opened 5 years ago
Closed 5 years ago
#1786 closed defect (fixed)
Send file from Perl module
| Reported by: | Owned by: | ||
|---|---|---|---|
| Priority: | minor | Milestone: | |
| Component: | nginx-module | Version: | 1.15.x |
| Keywords: | Cc: | ||
| uname -a: | Linux hk0 4.4.0-145-generic #171-Ubuntu SMP Tue Mar 26 12:43:40 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux | ||
| nginx -V: |
nginx version: nginx/1.16.0
built by gcc 4.8.5 20150623 (Red Hat 4.8.5-36) (GCC) built with OpenSSL 1.1.1b 26 Feb 2019 TLS SNI support enabled configure arguments: --with-cc-opt='-g -O2 -fstack-protector --param=ssp-buffer-size=4 -Wformat -Werror=format-security -D_FORTIFY_SOURCE=2' --with-ld-opt='-Wl,-Bsymbolic-functions -Wl,-z,relro' --prefix=/usr/share/nginx --sbin-path=/usr/sbin/nginx --conf-path=/etc/nginx/nginx.conf --http-log-path=/var/log/nginx/access.log --error-log-path=/var/log/nginx/error.log --lock-path=/var/lock/nginx.lock --pid-path=/run/nginx.pid --http-client-body-temp-path=/var/lib/nginx/body --http-proxy-temp-path=/var/lib/nginx/proxy --user=httpd --group=robot --with-http_ssl_module --with-http_realip_module --with-http_sub_module --with-http_flv_module --with-http_mp4_module --with-http_stub_status_module --with-file-aio --with-threads --with-http_v2_module --with-http_geoip_module --with-http_image_filter_module --with-http_perl_module --without-http_fastcgi_module --without-http_uwsgi_module --without-http_scgi_module --without-http_memcached_module --with-openssl=../openssl-1.1.1b --with-debug |
||
Description (last modified by )
(CentOS 7 container in Ubuntu 16 Server's Host)
stack:
(gdb) bt
#0 ngx_http_perl_output (r=r@entry=0x1e77480, b=b@entry=0x1e521d8) at nginx.xs:76
#1 0x00007f8512e2fc91 in XS_nginx_sendfile (my_perl=0xc7b700, cv=<optimized out>) at nginx.xs:751
#2 0x00007f8515b4541f in Perl_pp_entersub () from /usr/lib64/perl5/CORE/libperl.so
#3 0x00007f8515b3db96 in Perl_runops_standard () from /usr/lib64/perl5/CORE/libperl.so
#4 0x00007f8515ad5168 in Perl_call_sv () from /usr/lib64/perl5/CORE/libperl.so
#5 0x00000000004f34f6 in ngx_http_perl_call_handler (my_perl=my_perl@entry=0xc7b700, r=r@entry=0x1e77480,
nginx=<optimized out>, sub=0xdb9528, args=args@entry=0x0, handler=0x13d4100, rv=rv@entry=0x0)
at src/http/modules/perl/ngx_http_perl_module.c:710
#6 0x00000000004f4c35 in ngx_http_perl_handle_request (r=0x1e77480)
at src/http/modules/perl/ngx_http_perl_module.c:223
#7 0x00000000004f4e38 in ngx_http_perl_handler (r=<optimized out>) at src/http/modules/perl/ngx_http_perl_module.c:174
#8 0x000000000049acaf in ngx_http_core_content_phase (r=0x1e77480, ph=<optimized out>)
at src/http/ngx_http_core_module.c:1169
#9 0x00000000004953c5 in ngx_http_core_run_phases (r=0x1e77480) at src/http/ngx_http_core_module.c:858
#10 0x00000000004d6da8 in ngx_http_v2_run_request (r=0x1e77480) at src/http/v2/ngx_http_v2.c:3789
#11 0x00000000004d6e55 in ngx_http_v2_state_header_complete (h2c=0x1d32a10,
pos=0x185006b "i\213\344\307\362\027\235iǚy\317\347h\226\337=\277J\t\325/\224\212\b\001y@\212\343-\\d*bѿ%",
end=0x185006b "i\213\344\307\362\027\235iǚy\317\347h\226\337=\277J\t\325/\224\212\b\001y@\212\343-\\d*bѿ%")
at src/http/v2/ngx_http_v2.c:1704
#12 0x00000000004d7fff in ngx_http_v2_state_header_block (h2c=0x1d32a10,
pos=0x185006b "i\213\344\307\362\027\235iǚy\317\347h\226\337=\277J\t\325/\224\212\b\001y@\212\343-\\d*bѿ%",
end=0x185006b "i\213\344\307\362\027\235iǚy\317\347h\226\337=\277J\t\325/\224\212\b\001y@\212\343-\\d*bѿ%")
at src/http/v2/ngx_http_v2.c:1273
#13 0x00000000004d58a0 in ngx_http_v2_read_handler (rev=0x1794560) at src/http/v2/ngx_http_v2.c:413
#14 0x0000000000487329 in ngx_epoll_process_events (cycle=0xc5dd00, timer=<optimized out>, flags=<optimized out>)
at src/event/modules/ngx_epoll_module.c:902
#15 0x000000000047c3f7 in ngx_process_events_and_timers (cycle=cycle@entry=0xc5dd00) at src/event/ngx_event.c:242
#16 0x0000000000485015 in ngx_worker_process_cycle (cycle=cycle@entry=0xc5dd00, data=data@entry=0x27)
at src/os/unix/ngx_process_cycle.c:750
#17 0x000000000048363c in ngx_spawn_process (cycle=cycle@entry=0xc5dd00,
proc=proc@entry=0x484fd0 <ngx_worker_process_cycle>, data=data@entry=0x27,
name=name@entry=0x6e780e "worker process", respawn=respawn@entry=-3) at src/os/unix/ngx_process.c:199
#18 0x00000000004847d4 in ngx_start_worker_processes (cycle=cycle@entry=0xc5dd00, n=40, type=type@entry=-3)
at src/os/unix/ngx_process_cycle.c:359
#19 0x0000000000485c5f in ngx_master_process_cycle (cycle=cycle@entry=0xc5dd00) at src/os/unix/ngx_process_cycle.c:131
#20 0x000000000045acd2 in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:382
details:
#0 ngx_http_perl_output (r=r@entry=0x1e77480, b=b@entry=0x1e521d8) at nginx.xs:76
out = {buf = 0x0, next = 0x1e77480}
cl = <optimized out>
ctx = 0x0
#1 0x00007f8512e2fc91 in XS_nginx_sendfile (my_perl=0xc7b700, cv=<optimized out>) at nginx.xs:751
bytes = 6519719
clcf = 0x13d42d8
r = 0x1e77480
filename = <optimized out>
offset = 0
path = {len = 124,
…
reason:
ctx is equal to 0x0 (AKA NULL)
from sources (nginx.xs:76):
ctx = ngx_http_get_module_ctx(r, ngx_http_perl_module); // it looks ctx is equal to NULL here (maybe client is disconnected… who knows)
if (ctx->ssi) { // there is no ctx check here, so it crached on NULL
cl = ngx_alloc_chain_link(r->pool);
if (cl == NULL) {
return NGX_ERROR;
}
defect:
nginx workers massive crash (perhaps on file range requests)
Change History (18)
comment:1 by , 5 years ago
| Description: | modified (diff) |
|---|
comment:2 by , 5 years ago
I checked other nginx modules and found that they have ctx checking.
So I wrote a small "patch".
And after this "patch" (it looks like this diff):
~/work/nginx-1.16.0/src/http/modules/perl # diff nginx.xs nginx.xs.bak 75,76d74 < if (!ctx) < return NGX_ERROR; 384,385d381 < if (!ctx) < XSRETURN_UNDEF; 554,555d549 < if (!ctx) < XSRETURN_UNDEF; 797,798d790 < if (!ctx) < XSRETURN_EMPTY; 929,930d920 < if (!ctx) < XSRETURN_UNDEF; 1013,1014d1002 < if (!ctx) < XSRETURN_UNDEF;
I see no crashes anymore…
but instead I see "unlink file errors":
2019/06/01 20:51:21 [crit] 30246#30246: unlink() "/var/lib/nginx/cache/0/f2/2f13d0c26cfafad036a3297f41315f20" failed (2: No such file or directory) 2019/06/01 20:53:51 [crit] 30246#30246: unlink() "/var/lib/nginx/cache/0/f9/42465e88b56c6d4f1d33882dd2334f90" failed (2: No such file or directory) 2019/06/01 20:56:26 [crit] 30246#30246: unlink() "/var/lib/nginx/cache/0/9f/1555a5ac39d1c328c3509b2b903ea9f0" failed (2: No such file or directory) 2019/06/01 20:58:16 [crit] 30246#30246: unlink() "/var/lib/nginx/cache/0/95/29e2dbe2356beaaa0d914772153a6950" failed (2: No such file or directory) 2019/06/01 21:09:26 [crit] 30246#30246: unlink() "/var/lib/nginx/cache/d/bc/5a5b86b03b74efc293f7a9afe163cbcd" failed (2: No such file or directory) 2019/06/01 21:15:07 [crit] 30246#30246: unlink() "/var/lib/nginx/cache/d/ef/d89e6ad0bafa59da5ced1f26c156befd" failed (2: No such file or directory) 2019/06/01 21:25:27 [crit] 30246#30246: unlink() "/var/lib/nginx/cache/d/7f/ab54f84df18b83dbd63f38a1a45b87fd" failed (2: No such file or directory) 2019/06/01 21:27:27 [crit] 30246#30246: unlink() "/var/lib/nginx/cache/d/e8/7c9d4a83c66a19a9ed48ec5c73bcbe8d" failed (2: No such file or directory)
I checked error.log history for the last year, and found nothing like this.
So, I think it is an influence of my patch…
UP [next day]: no crashes and "unlink" error no longer repeats
p.s.
Sorry, Perl code is private, and just uses Postgres with standard DBI; I can't show it here.
comment:3 by , 5 years ago
Sorry, Perl code is private, and just uses Postgres with standard DBI; I can't show it here.
Feel free to show only nginx-related parts of the code. Also, as previously suggested, please provide full configuration.
Likely the culprit is either an attempt to output something after an internal redirect, or an error_page involving filter finalization. Perl module is known to be bad at handling errors, though it shouldn't result in segfaults unless a screwed up configuration and/or code is also involved.
follow-up: 5 comment:4 by , 5 years ago
I described modifications for original nginx.xs (https://trac.nginx.org/nginx/browser/nginx/src/http/modules/perl/nginx.xs) which fixes crash issue.
There wasn't a demo stand that can reproduce this eventually issue by request.
Modified version for nginx 1.16.0 (no crashes at all): https://www.dropbox.com/s/7i6ifp6qzkx2ieb/nginx.xs?dl=0
It solves NULL ctx issue based on core dumped.
Full configuration of what? configure options and uname were provided already.
Full nginx configuration?
Our nginx configuration is very big & monstrous, written by scripts, and not human readable.
We use Perl in nginx.conf for handlers like this:
location ~ ^/demo/\d+$ {
expires 2h;
keepalive_timeout 5s;
perl Demo::Nginx::FileDemo::handlerDirect;
error_page 403 405 = @backend;
access_log off;
}
Perl module Demo::Nginx::FileDemo part (simplified):
sub handlerDirect {
my $r = shift;
if ($r->request_method ne 'GET' && $r->request_method ne 'HEAD') {
return HTTP_BAD_REQUEST;
}
$r->discard_request_body;
# request uri
my $uri = $r->uri;
my $fileObj;
if ($uri =~ /\/(\d+)$/so)
{
my $fid = $1;
my $dbh = Demo::Nginx::DB->new();
$fileObj = $dbh->selectrow_hashref(q|select * from demos where id = ?|, {}, $fid);
}
return _sendFile($r, $fileObj);
}
sub _sendFile {
my ($r, $fileObj) = @_;
return HTTP_NOT_FOUND unless $fileObj;
my $lastModified;
my $contentLength;
my @stat = stat $fileObj->{file_path_site};
$lastModified = CGI::Util::expires($stat[9]);
$contentLength = $stat[7];
my $filename = $fileObj->{original_name};
unless (utf8::is_utf8($filename))
{
utf8::decode($filename);
}
$filename = url_encode_utf8($filename);
$filename =~ s|\+|%20|g;
my $outHeaderEtag = sprintf('W/"%s"', $fileObj->{id});
my $outHeaderLastModified = $lastModified || 'Fri, 18 Dec 2012 11:16:40 GMT';
$r->header_out('ETag', $outHeaderEtag);
$r->header_out('Last-Modified', $outHeaderLastModified);
$r->header_out('X-Demo', 'Demo::Nginx::FileDemo, file='.$fileObj->{id});
if ($outHeaderEtag eq $r->header_in("if-none-match") && $outHeaderLastModified eq $r->header_in("if-modified-since"))
{
# HTTP_NOT_MODIFIED
$r->header_only;
return HTTP_NOT_MODIFIED;
}
else
{
$r->header_out('Content-Disposition', qq|filename*=UTF-8''$filename|);
$r->header_out('Content-Length', $contentLength) if defined $contentLength;
$r->allow_ranges();
$r->send_http_header($fileObj->{file_type});
$r->sendfile($fileObj->{file_path_site});
return OK;
}
}
comment:5 by , 5 years ago
It solves NULL ctx issue based on core dumped.
While it may solve the issue for you, it doesn't explain why ctx is NULL. It is not expected to be NULL - except if there is a problem elsewhere. While some such problems - notably filter finalization - are known, they are expected to be easily avoidable. The question is if you are facing a known problem, or something different, and how to fix it properly. By adding ctx checks you are hiding symptoms, but do not fix the cause.
Full nginx configuration?
Sure. You can get one from nginx itself by running nginx -T.
Our nginx configuration is very big & monstrous, written by scripts, and not human readable.
This of course complicates things. Ideally, there should be a reduced configuration which doesn't contain unneeded details, but still enough to reproduce the issue.
We use Perl in nginx.conf for handlers like this:
location ~ ^/demo/\d+$ { expires 2h; keepalive_timeout 5s; perl Demo::Nginx::FileDemo::handlerDirect; error_page 403 405 = @backend; access_log off; }
Could you please confirm there are no error_page set for the following error codes: 412, 415 (if image_filter is used to process Perl responses), 500 (if xslt filter is used to process Perl responses)?
Also, it would be great to see a debug log with a segmentation fault, it may explain what leads to NULL ctx. Using in-memory debug logs might be a good solution if there is a lot of traffic and it is not possible to configure normal debug logging for some reason, see docs for details.
comment:6 by , 5 years ago
NXD1.HK0/mif: /etc/nginx # nginx -T | wc -l nginx: the configuration file /etc/nginx/nginx.conf syntax is ok nginx: configuration file /etc/nginx/nginx.conf test is successful
4734
NXD1.HK0/mif: /etc/nginx # nginx -T | grep error_page nginx: the configuration file /etc/nginx/nginx.conf syntax is ok nginx: configuration file /etc/nginx/nginx.conf test is successful error_page 404 = @dataSecondChance; error_page 404 /errors/404.html; error_page 403 /errors/403.html; error_page 404 /errors/404.html; error_page 500 /errors/500.html; error_page 501 /errors/501.html; error_page 502 /errors/502.html; error_page 503 /errors/503.html; error_page 504 /errors/504.html; error_page 403 /errors/403.html; error_page 404 /errors/404.html; error_page 500 /errors/500.html; error_page 501 /errors/501.html; error_page 502 /errors/502.html; error_page 503 /errors/503.html; error_page 504 /errors/504.html; error_page 403 /errors/403.html; error_page 404 /errors/404.html; error_page 500 /errors/500.html; error_page 501 /errors/501.html; error_page 502 /errors/502.html; error_page 503 /errors/503.html; error_page 504 /errors/504.html; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 403 405 = @backend; error_page 404 = /f/src/global/i/head_190.png; error_page 403 405 = @backend; error_page 404 = /f/src/global/i/head_190.png; error_page 404 = @dataSecondChance;
However our backend can actually reply with 412 code… only at one point – in case when backend can't do symlink for file from storage to a "random-ticket" place.
Additionally, there is 410 code – while file data doesn't exists physically.
But our nginx PM-module uses backend only in case of non public file. The major role of PM-module at nginx side – to serve public files.
About your suggestion about error_log in the debug mode – yep, I tried that first.
But we have 50 Mb logs (in the error_log file) per minute due to high-load project.
And error happens only once per hour or two… or four…
So there will be Gigs of unreadable logs… :-(
I checked other modules – and most of them have ctx checking.
comment:7 by , 5 years ago
4734
So, actually it is rather small.
About your suggestion about error_log in the debug mode – yep, I tried that first.
But we have 50 Mb logs (in the error_log file) per minute due to high-load project.
And error happens only once per hour or two… or four…
So there will be Gigs of unreadable logs… :-(
Well, several gigabytes of logs is not that many and can be easily handled by more or less any server. But see above about in-memory debug logs - these can be configured to use appropriately sized in-memory circular buffer, and their contents is available in a core dump, so they are well-suited for debugging segmentation faults.
comment:8 by , 5 years ago
I checked image_filter – yep, we use it, but for another location, so Perl handler works without it.
I tried circular error_log, and reverted my changes.
access log turned on also:
2.30.255.107 - - [05/Jun/2019:14:05:44 +0300] "GET /mirror/pubs/share/folder/89yx29u58z/direct/73244474 HTTP/2.0" 206 216136 "https://publications.hse.ru/mirror/pubs/share/folder/89yx29u58z/direct/73244474" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.140 Safari/537.36 Edge/17.17134" "-" "ticket=-,tracking=CgAGP1yiOoaZ3Sy2AxjgAg==,_lang=-" "-" "-" "[cs=-, request_time=0.263, upstream_response_time=-, upstream_response_length=-, upstream=-//-]" "[publications.hse.ru]" 2.30.255.107 - - [05/Jun/2019:14:05:45 +0300] "GET /mirror/pubs/share/folder/89yx29u58z/direct/73244474 HTTP/2.0" 206 117832 "https://publications.hse.ru/mirror/pubs/share/folder/89yx29u58z/direct/73244474" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.140 Safari/537.36 Edge/17.17134" "-" "ticket=-,tracking=CgAGP1yiOoaZ3Sy2AxjgAg==,_lang=-" "-" "-" "[cs=-, request_time=0.000, upstream_response_time=-, upstream_response_length=-, upstream=-//-]" "[publications.hse.ru]" 2.30.255.107 - - [05/Jun/2019:14:05:47 +0300] "GET /mirror/pubs/share/folder/89yx29u58z/direct/73244474 HTTP/2.0" 206 216136 "https://publications.hse.ru/mirror/pubs/share/folder/89yx29u58z/direct/73244474" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.140 Safari/537.36 Edge/17.17134" "-" "ticket=-,tracking=CgAGP1yiOoaZ3Sy2AxjgAg==,_lang=-" "-" "-" "[cs=-, request_time=0.525, upstream_response_time=-, upstream_response_length=-, upstream=-//-]" "[publications.hse.ru]" 2.30.255.107 - - [05/Jun/2019:14:05:50 +0300] "GET /mirror/pubs/share/folder/89yx29u58z/direct/73244474 HTTP/2.0" 206 3144 "https://publications.hse.ru/mirror/pubs/share/folder/89yx29u58z/direct/73244474" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.140 Safari/537.36 Edge/17.17134" "-" "ticket=-,tracking=CgAGP1yiOoaZ3Sy2AxjgAg==,_lang=-" "-" "-" "[cs=-, request_time=0.000, upstream_response_time=-, upstream_response_length=-, upstream=-//-]" "[publications.hse.ru]"
gdb bt full:
NXD1.HK0/mif: /tmp # gdb /sbin/nginx core.nginx.30611
GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-114.el7
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/sbin/nginx...done.
[New LWP 30611]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `nginx: worke'.
Program terminated with signal 11, Segmentation fault.
#0 ngx_http_perl_output (r=r@entry=0x41b7080, b=b@entry=0x39a20f0) at nginx.xs:78
78 if (ctx->ssi) {
Missing separate debuginfos, use: debuginfo-install GeoIP-1.5.0-13.el7.x86_64 bzip2-libs-1.0.6-13.el7.x86_64 cyrus-sasl-lib-2.1.26-23.el7.x86_64 expat-2.1.0-10.el7_3.x86_64 fontconfig-2.13.0-4.3.el7.x86_64 freetype-2.8-12.el7_6.1.x86_64 gd-2.0.35-26.el7.x86_64 keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.15.1-37.el7_6.x86_64 libX11-1.6.5-2.el7.x86_64 libXau-1.0.8-2.1.el7.x86_64 libXpm-3.5.12-1.el7.x86_64 libcom_err-1.42.9-13.el7.x86_64 libjpeg-turbo-1.2.90-6.el7.x86_64 libpng-1.5.13-7.el7_2.x86_64 libuuid-2.23.2-59.el7_6.1.x86_64 libxcb-1.13-1.el7.x86_64 nspr-4.19.0-1.el7_5.x86_64 nss-3.36.0-7.1.el7_6.x86_64 nss-util-3.36.0-1.1.el7_6.x86_64 openldap-2.4.44-21.el7_6.x86_64 pcre-8.32-17.el7.x86_64 perl-DBD-Pg-2.19.3-4.el7.x86_64 perl-DBI-1.627-4.el7.x86_64 perl-Scalar-List-Utils-1.27-248.el7.x86_64 perl-libs-5.16.3-294.el7_6.x86_64 perl-version-0.99.07-3.el7.x86_64 postgresql-libs-9.2.24-1.el7_5.x86_64 zlib-1.2.7-18.el7.x86_64
(gdb) bt full
#0 ngx_http_perl_output (r=r@entry=0x41b7080, b=b@entry=0x39a20f0) at nginx.xs:78
out = {buf = 0x0, next = 0x41b7080}
cl = <optimized out>
ctx = 0x0
#1 0x00007f7ba8bd7d34 in XS_nginx_sendfile (my_perl=0x29f7750, cv=<optimized out>) at nginx.xs:757
bytes = 216136
clcf = 0x3158880
r = 0x41b7080
filename = <optimized out>
offset = 0
path = {len = 121,
data = 0x39a2228 "/some/path/data/2013/2/5/1360063049/73244474/somefile.pdf"}
b = 0x39a20f0
of = {fd = 787, uniq = 214696727, mtime = 1360063049, size = 216136, fs_size = 217088, directio = 9223372036854775807,
read_ahead = 0, err = 0, failed = 0x0, valid = 100, min_uses = 2, disable_symlinks_from = 0, disable_symlinks = 0, test_dir = 0,
test_only = 0, log = 0, errors = 1, events = 0, is_dir = 0, is_file = 1, is_link = 0, is_exec = 0, is_directio = 0}
sp = <optimized out>
ax = <optimized out>
mark = <optimized out>
items = <optimized out>
#2 0x00007f7bad8ee41f in Perl_pp_entersub () from /usr/lib64/perl5/CORE/libperl.so
No symbol table info available.
#3 0x00007f7bad8e6b96 in Perl_runops_standard () from /usr/lib64/perl5/CORE/libperl.so
No symbol table info available.
#4 0x00007f7bad87e168 in Perl_call_sv () from /usr/lib64/perl5/CORE/libperl.so
No symbol table info available.
#5 0x00000000004f34f6 in ngx_http_perl_call_handler (my_perl=my_perl@entry=0x29f7750, r=r@entry=0x41b7080, nginx=<optimized out>,
sub=0x2b355d8, args=args@entry=0x0, handler=0x3159398, rv=rv@entry=0x0) at src/http/modules/perl/ngx_http_perl_module.c:710
sv = <optimized out>
n = <optimized out>
status = 0
line = <optimized out>
err = <optimized out>
len = 140729496734479
n_a = 15
i = <optimized out>
c = 0x3f6c010
sp = 0x36e6268
#6 0x00000000004f4c35 in ngx_http_perl_handle_request (r=0x41b7080) at src/http/modules/perl/ngx_http_perl_module.c:223
my_perl = 0x29f7750
sub = <optimized out>
rc = <optimized out>
uri = {len = 68908112, data = 0x41b7080 "HTTP"}
args = {len = 59148024, data = 0x34128e2 "pubs/share/preprint/cover/"}
handler = <optimized out>
ctx = 0x41b7e30
plcf = <optimized out>
pmcf = 0x29dd9b0
---Type <return> to continue, or q <return> to quit---
#7 0x00000000004f4e38 in ngx_http_perl_handler (r=<optimized out>) at src/http/modules/perl/ngx_http_perl_module.c:174
No locals.
#8 0x000000000049acaf in ngx_http_core_content_phase (r=0x41b7080, ph=<optimized out>) at src/http/ngx_http_core_module.c:1169
root = 68907136
rc = <optimized out>
path = {len = 54605600,
data = 0x499a33 <ngx_http_core_generic_phase+35> "H\205\300tPH\203\370\373tbH\211\302\061\355H\203\342\375H\203\372\374t\vH\211\306H\211\337\350xd"}
#9 0x00000000004953c5 in ngx_http_core_run_phases (r=0x41b7080) at src/http/ngx_http_core_module.c:858
rc = <optimized out>
ph = 0x3413600
cmcf = <optimized out>
#10 0x00000000004d6da8 in ngx_http_v2_run_request (r=0x41b7080) at src/http/v2/ngx_http_v2.c:3789
fc = 0x3f6c010
#11 0x00000000004d6e55 in ngx_http_v2_state_header_complete (h2c=0x420a990,
pos=0x35dd79d "7C\352\243\336\273\272\037\033\360\303\064\020\177S\242\035u\320b\r&=LtA\352\372Q%\362\226:\017\270\320K\rZ~\224\371c\347\355N\320\001p\a_\213\035u\320b\r&=LtA\352@\205=\206\230\325\177\215\235)\255\027\030a\025Ƽ\350*\366[P\215\216ϥ&\366j\376\224\220\262\320\064\227z\340\320\177f\242\201\260\332\340S\372\066\261\311\366\245\355|\024չ@\212!)A\272\225M\003\"\232\267)\371\375\251\ru\320^E\217\061\222Àmp\256\026\324\376\263cߣ?Ҕ\033\251T\304Ru?\366\247\022\036\246\002%¦\203\306j\n\300[\300\026\236Sp\345\035\206a\300\064\270\177\310Q\002"...,
end=0x35dd79d "7C\352\243\336\273\272\037\033\360\303\064\020\177S\242\035u\320b\r&=LtA\352\372Q%\362\226:\017\270\320K\rZ~\224\371c\347\355N\320\001p\a_\213\035u\320b\r&=LtA\352@\205=\206\230\325\177\215\235)\255\027\030a\025Ƽ\350*\366[P\215\216ϥ&\366j\376\224\220\262\320\064\227z\340\320\177f\242\201\260\332\340S\372\066\261\311\366\245\355|\024չ@\212!)A\272\225M\003\"\232\267)\371\375\251\ru\320^E\217\061\222Àmp\256\026\324\376\263cߣ?Ҕ\033\251T\304Ru?\366\247\022\036\246\002%¦\203\306j\n\300[\300\026\236Sp\345\035\206a\300\064\270\177\310Q\002"...) at src/http/v2/ngx_http_v2.c:1704
stream = <optimized out>
end = 0x35dd79d "7C\352\243\336\273\272\037\033\360\303\064\020\177S\242\035u\320b\r&=LtA\352\372Q%\362\226:\017\270\320K\rZ~\224\371c\347\355N\320\001p\a_\213\035u\320b\r&=LtA\352@\205=\206\230\325\177\215\235)\255\027\030a\025Ƽ\350*\366[P\215\216ϥ&\366j\376\224\220\262\320\064\227z\340\320\177f\242\201\260\332\340S\372\066\261\311\366\245\355|\024չ@\212!)A\272\225M\003\"\232\267)\371\375\251\ru\320^E\217\061\222Àmp\256\026\324\376\263cߣ?Ҕ\033\251T\304Ru?\366\247\022\036\246\002%¦\203\306j\n\300[\300\026\236Sp\345\035\206a\300\064\270\177\310Q\002"...
pos = 0x35dd79d "7C\352\243\336\273\272\037\033\360\303\064\020\177S\242\035u\320b\r&=LtA\352\372Q%\362\226:\017\270\320K\rZ~\224\371c\347\355N\320\001p\a_\213\035u\320b\r&=LtA\352@\205=\206\230\325\177\215\235)\255\027\030a\025Ƽ\350*\366[P\215\216ϥ&\366j\376\224\220\262\320\064\227z\340\320\177f\242\201\260\332\340S\372\066\261\311\366\245\355|\024չ@\212!)A\272\225M\003\"\232\267)\371\375\251\ru\320^E\217\061\222Àmp\256\026\324\376\263cߣ?Ҕ\033\251T\304Ru?\366\247\022\036\246\002%¦\203\306j\n\300[\300\026\236Sp\345\035\206a\300\064\270\177\310Q\002"...
h2c = 0x420a990
#12 0x00000000004d7d3d in ngx_http_v2_state_field_len (h2c=h2c@entry=0x420a990,
pos=0x35dd783 "M\203'SU4\027\246\207\026\260\372\066\243\217\365\235ޅ\017\236\223C4\020\177\067C\352\243\336\273\272\037\033\360\303\064\020\177S\242\035u\320b\r&=LtA\352\372Q%\362\226:\017\270\320K\rZ~\224\371c\347\355N\320\001p\a_\213\035u\320b\r&=LtA\352@\205=\206\230\325\177\215\235)\255\027\030a\025Ƽ\350*\366[P\215\216ϥ&\366j\376\224\220\262\320\064\227z\340\320\177f\242\201\260\332\340S\372\066\261\311\366\245\355|\024չ@\212!)A\272\225M\003\"\232\267)\371\375\251\ru\320^E\217\061\222Àmp\256\026\324\376\263cߣ?Ҕ\033\251T\304Ru?\366\247\022\036\246"...,
end=end@entry=0x35dd79d "7C\352\243\336\273\272\037\033\360\303\064\020\177S\242\035u\320b\r&=LtA\352\372Q%\362\226:\017\270\320K\rZ~\224\371c\347\355N\320\001p\a_\213\035u\320b\r&=LtA\352@\205=\206\230\325\177\215\235)\255\027\030a\025Ƽ\350*\366[P\215\216ϥ&\366j\376\224\220\262\320\064\227z\340\320\177f\242\201\260\332\340S\372\066\261\311\366\245\355|\024չ@\212!)A\272\225M\003\"\232\267)\371\375\251\ru\320^E\217\061\222Àmp\256\026\324\376\263cߣ?Ҕ\033\251T\304Ru?\366\247\022\036\246\002%¦\203\306j\n\300[\300\026\236Sp\345\035\206a\300\064\270\177\310Q\002"...) at src/http/v2/ngx_http_v2.c:1377
alloc = <optimized out>
---Type <return> to continue, or q <return> to quit---
len = <optimized out>
huff = 1
h2scf = <optimized out>
#13 0x00000000004d7e64 in ngx_http_v2_state_header_block (h2c=0x420a990, pos=<optimized out>,
end=0x35dd79d "7C\352\243\336\273\272\037\033\360\303\064\020\177S\242\035u\320b\r&=LtA\352\372Q%\362\226:\017\270\320K\rZ~\224\371c\347\355N\320\001p\a_\213\035u\320b\r&=LtA\352@\205=\206\230\325\177\215\235)\255\027\030a\025Ƽ\350*\366[P\215\216ϥ&\366j\376\224\220\262\320\064\227z\340\320\177f\242\201\260\332\340S\372\066\261\311\366\245\355|\024չ@\212!)A\272\225M\003\"\232\267)\371\375\251\ru\320^E\217\061\222Àmp\256\026\324\376\263cߣ?Ҕ\033\251T\304Ru?\366\247\022\036\246\002%¦\203\306j\n\300[\300\026\236Sp\345\035\206a\300\064\270\177\310Q\002"...) at src/http/v2/ngx_http_v2.c:1293
ch = <optimized out>
value = <optimized out>
indexed = 0
size_update = 0
prefix = <optimized out>
#14 0x00000000004d58a0 in ngx_http_v2_read_handler (rev=0x3515080) at src/http/v2/ngx_http_v2.c:413
p = <optimized out>
end = 0x35dd79d "7C\352\243\336\273\272\037\033\360\303\064\020\177S\242\035u\320b\r&=LtA\352\372Q%\362\226:\017\270\320K\rZ~\224\371c\347\355N\320\001p\a_\213\035u\320b\r&=LtA\352@\205=\206\230\325\177\215\235)\255\027\030a\025Ƽ\350*\366[P\215\216ϥ&\366j\376\224\220\262\320\064\227z\340\320\177f\242\201\260\332\340S\372\066\261\311\366\245\355|\024չ@\212!)A\272\225M\003\"\232\267)\371\375\251\ru\320^E\217\061\222Àmp\256\026\324\376\263cߣ?Ҕ\033\251T\304Ru?\366\247\022\036\246\002%¦\203\306j\n\300[\300\026\236Sp\345\035\206a\300\064\270\177\310Q\002"...
n = <optimized out>
c = 0x341e9f8
h2mcf = 0x29dcf38
h2c = 0x420a990
#15 0x0000000000487329 in ngx_epoll_process_events (cycle=0x29d9d30, timer=<optimized out>, flags=<optimized out>)
at src/event/modules/ngx_epoll_module.c:902
events = <optimized out>
revents = 1
instance = <optimized out>
i = 0
level = <optimized out>
err = <optimized out>
rev = 0x3515080
wev = <optimized out>
queue = <optimized out>
c = 0x341e9f8
#16 0x000000000047c3f7 in ngx_process_events_and_timers (cycle=cycle@entry=0x29d9d30) at src/event/ngx_event.c:242
flags = <optimized out>
timer = <optimized out>
delta = 4989836509
#17 0x0000000000485015 in ngx_worker_process_cycle (cycle=cycle@entry=0x29d9d30, data=data@entry=0x24)
at src/os/unix/ngx_process_cycle.c:750
worker = 36
#18 0x000000000048363c in ngx_spawn_process (cycle=cycle@entry=0x29d9d30, proc=proc@entry=0x484fd0 <ngx_worker_process_cycle>,
data=data@entry=0x24, name=name@entry=0x6e780e "worker process", respawn=respawn@entry=-3) at src/os/unix/ngx_process.c:199
on = 1
pid = 0
s = 36
---Type <return> to continue, or q <return> to quit---
#19 0x00000000004847d4 in ngx_start_worker_processes (cycle=cycle@entry=0x29d9d30, n=40, type=type@entry=-3)
at src/os/unix/ngx_process_cycle.c:359
i = 36
ch = {command = 1, pid = 30610, slot = 35, fd = 85}
#20 0x0000000000485c5f in ngx_master_process_cycle (cycle=cycle@entry=0x29d9d30) at src/os/unix/ngx_process_cycle.c:131
title = 0x3413e5c "master process /sbin/nginx"
MEMLOG 33554432 /etc/nginx/nginx.conf:7
2019/06/05 13:57:10 [debug] 30573#30573: bind() 0.0.0.0:80 #13
2019/06/05 13:57:10 [debug] 30573#30573: bind() 0.0.0.0:443 #14
2019/06/05 13:57:10 [debug] 30573#30573: bind() 0.0.0.0:11099 #15
2019/06/05 13:57:10 [debug] 30573#30573: posix_memalign: 0000000003418040:16384 @16
2019/06/05 13:57:10 [notice] 30573#30573: using the "epoll" event method
2019/06/05 13:57:10 [debug] 30573#30573: counter: 00007F7BAED25080, 1
2019/06/05 13:57:10 [notice] 30573#30573: nginx/1.16.0
2019/06/05 13:57:10 [notice] 30573#30573: built by gcc 4.8.5 20150623 (Red Hat 4.8.5-36) (GCC)
2019/06/05 13:57:10 [notice] 30573#30573: OS: Linux 4.4.0-145-generic
2019/06/05 13:57:10 [notice] 30573#30573: getrlimit(RLIMIT_NOFILE): 1048576:1048576
2019/06/05 13:57:10 [debug] 30574#30574: write: 16, 00007FFE23A98F90, 6, 0
2019/06/05 13:57:10 [debug] 30574#30574: setproctitle: "nginx: master process /sbin/nginx"
2019/06/05 13:57:10 [notice] 30574#30574: start worker processes
2019/06/05 13:57:10 [debug] 30574#30574: channel 3:16
2019/06/05 13:57:10 [notice] 30574#30574: start worker process 30575
2019/06/05 13:57:10 [debug] 30574#30574: channel 17:18
2019/06/05 13:57:10 [notice] 30574#30574: start worker process 30576
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:1 pid:30576 fd:17 to s:0 pid:30575 fd:3
2019/06/05 13:57:10 [debug] 30574#30574: channel 19:20
2019/06/05 13:57:10 [notice] 30574#30574: start worker process 30577
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:2 pid:30577 fd:19 to s:0 pid:30575 fd:3
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:2 pid:30577 fd:19 to s:1 pid:30576 fd:17
2019/06/05 13:57:10 [debug] 30574#30574: channel 21:22
2019/06/05 13:57:10 [notice] 30574#30574: start worker process 30578
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:3 pid:30578 fd:21 to s:0 pid:30575 fd:3
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:3 pid:30578 fd:21 to s:1 pid:30576 fd:17
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:3 pid:30578 fd:21 to s:2 pid:30577 fd:19
2019/06/05 13:57:10 [debug] 30574#30574: channel 23:24
2019/06/05 13:57:10 [notice] 30574#30574: start worker process 30579
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:4 pid:30579 fd:23 to s:0 pid:30575 fd:3
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:4 pid:30579 fd:23 to s:1 pid:30576 fd:17
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:4 pid:30579 fd:23 to s:2 pid:30577 fd:19
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:4 pid:30579 fd:23 to s:3 pid:30578 fd:21
2019/06/05 13:57:10 [debug] 30574#30574: channel 25:26
2019/06/05 13:57:10 [notice] 30574#30574: start worker process 30580
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:5 pid:30580 fd:25 to s:0 pid:30575 fd:3
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:5 pid:30580 fd:25 to s:1 pid:30576 fd:17
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:5 pid:30580 fd:25 to s:2 pid:30577 fd:19
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:5 pid:30580 fd:25 to s:3 pid:30578 fd:21
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:5 pid:30580 fd:25 to s:4 pid:30579 fd:23
2019/06/05 13:57:10 [debug] 30574#30574: channel 27:28
2019/06/05 13:57:10 [notice] 30574#30574: start worker process 30581
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:6 pid:30581 fd:27 to s:0 pid:30575 fd:3
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:6 pid:30581 fd:27 to s:1 pid:30576 fd:17
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:6 pid:30581 fd:27 to s:2 pid:30577 fd:19
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:6 pid:30581 fd:27 to s:3 pid:30578 fd:21
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:6 pid:30581 fd:27 to s:4 pid:30579 fd:23
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:6 pid:30581 fd:27 to s:5 pid:30580 fd:25
/14:05
p = <optimized out>
size = <optimized out>
i = <optimized out>
n = <optimized out>
sigio = <optimized out>
set = {__val = {0 <repeats 16 times>}}
itv = {it_interval = {tv_sec = 0, tv_usec = 0}, it_value = {tv_sec = 0, tv_usec = 0}}
live = <optimized out>
delay = <optimized out>
ls = <optimized out>
MEMLOG 33554432 /etc/nginx/nginx.conf:7
2019/06/05 13:57:10 [debug] 30573#30573: bind() 0.0.0.0:80 #13
2019/06/05 13:57:10 [debug] 30573#30573: bind() 0.0.0.0:443 #14
2019/06/05 13:57:10 [debug] 30573#30573: bind() 0.0.0.0:11099 #15
2019/06/05 13:57:10 [debug] 30573#30573: posix_memalign: 0000000003418040:16384 @16
2019/06/05 13:57:10 [notice] 30573#30573: using the "epoll" event method
2019/06/05 13:57:10 [debug] 30573#30573: counter: 00007F7BAED25080, 1
2019/06/05 13:57:10 [notice] 30573#30573: nginx/1.16.0
2019/06/05 13:57:10 [notice] 30573#30573: built by gcc 4.8.5 20150623 (Red Hat 4.8.5-36) (GCC)
2019/06/05 13:57:10 [notice] 30573#30573: OS: Linux 4.4.0-145-generic
2019/06/05 13:57:10 [notice] 30573#30573: getrlimit(RLIMIT_NOFILE): 1048576:1048576
2019/06/05 13:57:10 [debug] 30574#30574: write: 16, 00007FFE23A98F90, 6, 0
2019/06/05 13:57:10 [debug] 30574#30574: setproctitle: "nginx: master process /sbin/nginx"
2019/06/05 13:57:10 [notice] 30574#30574: start worker processes
2019/06/05 13:57:10 [debug] 30574#30574: channel 3:16
2019/06/05 13:57:10 [notice] 30574#30574: start worker process 30575
2019/06/05 13:57:10 [debug] 30574#30574: channel 17:18
2019/06/05 13:57:10 [notice] 30574#30574: start worker process 30576
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:1 pid:30576 fd:17 to s:0 pid:30575 fd:3
2019/06/05 13:57:10 [debug] 30574#30574: channel 19:20
2019/06/05 13:57:10 [notice] 30574#30574: start worker process 30577
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:2 pid:30577 fd:19 to s:0 pid:30575 fd:3
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:2 pid:30577 fd:19 to s:1 pid:30576 fd:17
2019/06/05 13:57:10 [debug] 30574#30574: channel 21:22
2019/06/05 13:57:10 [notice] 30574#30574: start worker process 30578
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:3 pid:30578 fd:21 to s:0 pid:30575 fd:3
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:3 pid:30578 fd:21 to s:1 pid:30576 fd:17
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:3 pid:30578 fd:21 to s:2 pid:30577 fd:19
2019/06/05 13:57:10 [debug] 30574#30574: channel 23:24
2019/06/05 13:57:10 [notice] 30574#30574: start worker process 30579
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:4 pid:30579 fd:23 to s:0 pid:30575 fd:3
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:4 pid:30579 fd:23 to s:1 pid:30576 fd:17
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:4 pid:30579 fd:23 to s:2 pid:30577 fd:19
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:4 pid:30579 fd:23 to s:3 pid:30578 fd:21
2019/06/05 13:57:10 [debug] 30574#30574: channel 25:26
2019/06/05 13:57:10 [notice] 30574#30574: start worker process 30580
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:5 pid:30580 fd:25 to s:0 pid:30575 fd:3
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:5 pid:30580 fd:25 to s:1 pid:30576 fd:17
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:5 pid:30580 fd:25 to s:2 pid:30577 fd:19
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:5 pid:30580 fd:25 to s:3 pid:30578 fd:21
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:5 pid:30580 fd:25 to s:4 pid:30579 fd:23
2019/06/05 13:57:10 [debug] 30574#30574: channel 27:28
2019/06/05 13:57:10 [notice] 30574#30574: start worker process 30581
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:6 pid:30581 fd:27 to s:0 pid:30575 fd:3
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:6 pid:30581 fd:27 to s:1 pid:30576 fd:17
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:6 pid:30581 fd:27 to s:2 pid:30577 fd:19
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:6 pid:30581 fd:27 to s:3 pid:30578 fd:21
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:6 pid:30581 fd:27 to s:4 pid:30579 fd:23
2019/06/05 13:57:10 [debug] 30574#30574: pass channel s:6 pid:30581 fd:27 to s:5 pid:30580 fd:25
/14:05:49
ccf = 0x29dbb78
#21 0x000000000045acd2 in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:382
b = <optimized out>
log = 0x9f8fc0 <ngx_log>
i = <optimized out>
cycle = 0x29d9d30
init_cycle = {conf_ctx = 0x0, pool = 0x29d8f70, log = 0x9f8fc0 <ngx_log>, new_log = {log_level = 0, file = 0x0, connection = 0,
disk_full_time = 0, handler = 0x0, data = 0x0, writer = 0x0, wdata = 0x0, action = 0x0, next = 0x0}, log_use_stderr = 0,
files = 0x0, free_connections = 0x0, free_connection_n = 0, modules = 0x0, modules_n = 0, modules_used = 0,
reusable_connections_queue = {prev = 0x0, next = 0x0}, reusable_connections_n = 0, listening = {elts = 0x0, nelts = 0, size = 0,
nalloc = 0, pool = 0x0}, paths = {elts = 0x0, nelts = 0, size = 0, nalloc = 0, pool = 0x0}, config_dump = {elts = 0x0,
nelts = 0, size = 0, nalloc = 0, pool = 0x0}, config_dump_rbtree = {root = 0x0, sentinel = 0x0, insert = 0x0},
config_dump_sentinel = {key = 0, left = 0x0, right = 0x0, parent = 0x0, color = 0 '\000', data = 0 '\000'}, open_files = {
last = 0x0, part = {elts = 0x0, nelts = 0, next = 0x0}, size = 0, nalloc = 0, pool = 0x0}, shared_memory = {last = 0x0,
part = {elts = 0x0, nelts = 0, next = 0x0}, size = 0, nalloc = 0, pool = 0x0}, connection_n = 0, files_n = 0,
connections = 0x0, read_events = 0x0, write_events = 0x0, old_cycle = 0x0, conf_file = {len = 21,
data = 0x6e220e "/etc/nginx/nginx.conf"}, conf_param = {len = 0, data = 0x0}, conf_prefix = {len = 11,
data = 0x6e220e "/etc/nginx/nginx.conf"}, prefix = {len = 17, data = 0x6e21fc "/usr/share/nginx/"}, lock_file = {len = 0,
data = 0x0}, hostname = {len = 0, data = 0x0}}
cd = <optimized out>
ccf = <optimized out>
(gdb) set $log = ngx_cycle->log
(gdb)
(gdb) while $log->writer != ngx_log_memory_writer
> set $log = $log->next
>end
(gdb)
(gdb) set $buf = (ngx_log_memory_buf_t *) $log->wdata
(gdb) dump binary memory debug_log.txt $buf->start $buf->end
(gdb) quit
debug_log.txt tail:
… 2019/06/05 14:05:49 [debug] 30611#30611: worker cycle 2019/06/05 14:05:49 [debug] 30611#30611: epoll timer: 689 2019/06/05 14:05:49 [debug] 30611#30611: epoll: fd:695 ev:0005 d:000000000341F691 2019/06/05 14:05:49 [debug] 30611#30611: timer delta: 8 2019/06/05 14:05:49 [debug] 30611#30611: worker cycle 2019/06/05 14:05:49 [debug] 30611#30611: epoll timer: 681 2019/06/05 14:05:49 [debug] 30611#30611: epoll: fd:722 ev:0001 d:000000000341CFD1 2019/06/05 14:05:49 [debug] 30611#30611: timer delta: 12 2019/06/05 14:05:49 [debug] 30611#30611: worker cycle 2019/06/05 14:05:49 [debug] 30611#30611: epoll timer: 669 2019/06/05 14:05:49 [debug] 30611#30611: epoll: fd:543 ev:0005 d:00000000034287E1 2019/06/05 14:05:49 [debug] 30611#30611: shmtx lock 2019/06/05 14:05:49 [debug] 30611#30611: shmtx unlock 2019/06/05 14:05:49 [debug] 30611#30611: timer delta: 12 2019/06/05 14:05:49 [debug] 30611#30611: worker cycle 2019/06/05 14:05:49 [debug] 30611#30611: epoll timer: 390 2019/06/05 14:05:49 [debug] 30611#30611: epoll: fd:722 ev:0001 d:000000000341CFD1 2019/06/05 14:05:49 [debug] 30611#30611: shmtx lock 2019/06/05 14:05:49 [debug] 30611#30611: shmtx unlock 2019/06/05 14:05:49 [debug] 30611#30611: timer delta: 16 2019/06/05 14:05:49 [debug] 30611#30611: worker cycle 2019/06/05 14:05:49 [debug] 30611#30611: epoll timer: 374 2019/06/05 14:05:49 [debug] 30611#30611: epoll: fd:684 ev:0001 d:000000000341E9F8 2019/06/05 14:05:49 [debug] 30611#30611: timer delta: 4 2019/06/05 14:05:49 [debug] 30611#30611: worker cycle 2019/06/05 14:05:49 [debug] 30611#30611: epoll timer: 370 2019/06/05 14:05:49 [debug] 30611#30611: epoll: fd:684 ev:0001 d:000000000341E9F8 2019/06/05 14:05:49 [debug] 30611#30611: timer delta: 0 2019/06/05 14:05:49 [debug] 30611#30611: worker cycle 2019/06/05 14:05:49 [debug] 30611#30611: epoll timer: 370 2019/06/05 14:05:49 [debug] 30611#30611: epoll: fd:684 ev:0001 d:000000000341E9F8
Code 206 – so, it looks like my hypothesis about partial content query confirmed…
The full link: https://www.hse.ru//mirror/pubs/share/folder/89yx29u58z/direct/73244474
but it seems to work.
follow-up: 10 comment:9 by , 5 years ago
The log snippet suggests that you've only configured debug log at the global level, but it is then overridden by other error_log directives at other levels (http/server/location). Please comment out these error_log directives as recommended at A debugging log article, or add appropriate error_log to memory along with these directives.
comment:10 by , 5 years ago
Replying to mdounin:
The log snippet suggests that you've only configured debug log at the global level, but it is then overridden by other
error_logdirectives at other levels (http/server/location). Please comment out these error_log directives as recommended at A debugging log article, or add appropriate error_log to memory along with these directives.
NXD1.HK0/mif: /etc/nginx # nginx -T | grep error_log nginx: the configuration file /etc/nginx/nginx.conf syntax is ok nginx: configuration file /etc/nginx/nginx.conf test is successful error_log memory:32m debug;
is it wrong?
comment:11 by , 5 years ago
Looks fine, not sure why the snippet looks so weird though. Please provide full contents of debug_log.txt then.
Also please provide output of the following gdb commands:
fr 0 p *r p *r->connection p r->connection->number
comment:12 by , 5 years ago
ok, next experiment…
Full PDF link: https://grans.hse.ru/mirror/pubs/share/266848717
Core stat:
NXD1.HK0/mif: /tmp # stat core.nginx.22728 … Modified: 2019-06-05 16:42:55.219917719 +0300
gdb bt full + data commands:
NXD1.HK0/mif: /tmp # gdb /sbin/nginx core.nginx.22728
GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-114.el7
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/sbin/nginx...done.
[New LWP 22728]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `nginx: worke'.
Program terminated with signal 11, Segmentation fault.
#0 ngx_http_perl_output (r=r@entry=0x1be3ba0, b=b@entry=0x1d3cd30) at nginx.xs:78
78 if (ctx->ssi) {
Missing separate debuginfos, use: debuginfo-install GeoIP-1.5.0-13.el7.x86_64 bzip2-libs-1.0.6-13.el7.x86_64 cyrus-sasl-lib-2.1.26-23.el7.x86_64 expat-2.1.0-10.el7_3.x86_64 fontconfig-2.13.0-4.3.el7.x86_64 freetype-2.8-12.el7_6.1.x86_64 gd-2.0.35-26.el7.x86_64 keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.15.1-37.el7_6.x86_64 libX11-1.6.5-2.el7.x86_64 libXau-1.0.8-2.1.el7.x86_64 libXpm-3.5.12-1.el7.x86_64 libcom_err-1.42.9-13.el7.x86_64 libjpeg-turbo-1.2.90-6.el7.x86_64 libpng-1.5.13-7.el7_2.x86_64 libuuid-2.23.2-59.el7_6.1.x86_64 libxcb-1.13-1.el7.x86_64 nspr-4.19.0-1.el7_5.x86_64 nss-3.36.0-7.1.el7_6.x86_64 nss-util-3.36.0-1.1.el7_6.x86_64 openldap-2.4.44-21.el7_6.x86_64 pcre-8.32-17.el7.x86_64 perl-DBD-Pg-2.19.3-4.el7.x86_64 perl-DBI-1.627-4.el7.x86_64 perl-Scalar-List-Utils-1.27-248.el7.x86_64 perl-libs-5.16.3-294.el7_6.x86_64 perl-version-0.99.07-3.el7.x86_64 postgresql-libs-9.2.24-1.el7_5.x86_64 zlib-1.2.7-18.el7.x86_64
(gdb) bt full
#0 ngx_http_perl_output (r=r@entry=0x1be3ba0, b=b@entry=0x1d3cd30) at nginx.xs:78
out = {buf = 0x0, next = 0x1be3ba0}
cl = <optimized out>
ctx = 0x0
#1 0x00007f37d0e81d34 in XS_nginx_sendfile (my_perl=0x176df30, cv=<optimized out>) at nginx.xs:757
bytes = 233366
clcf = 0x1f4f378
r = 0x1be3ba0
filename = <optimized out>
offset = 0
path = {len = 124,
data = 0x1d3ce68 "/some/path/data/2019/04/27/1556339997/266848717/somefile.pdf"}
b = 0x1d3cd30
of = {fd = 61, uniq = 32702986, mtime = 1556339997, size = 233366, fs_size = 233472, directio = 9223372036854775807,
read_ahead = 0, err = 0, failed = 0x0, valid = 100, min_uses = 2, disable_symlinks_from = 0, disable_symlinks = 0, test_dir = 0,
test_only = 0, log = 0, errors = 1, events = 0, is_dir = 0, is_file = 1, is_link = 0, is_exec = 0, is_directio = 0}
sp = <optimized out>
ax = <optimized out>
mark = <optimized out>
items = <optimized out>
#2 0x00007f37d5b9841f in Perl_pp_entersub () from /usr/lib64/perl5/CORE/libperl.so
No symbol table info available.
#3 0x00007f37d5b90b96 in Perl_runops_standard () from /usr/lib64/perl5/CORE/libperl.so
No symbol table info available.
#4 0x00007f37d5b28168 in Perl_call_sv () from /usr/lib64/perl5/CORE/libperl.so
No symbol table info available.
#5 0x00000000004f34f6 in ngx_http_perl_call_handler (my_perl=my_perl@entry=0x176df30, r=r@entry=0x1be3ba0, nginx=<optimized out>,
sub=0x17cb610, args=args@entry=0x0, handler=0x1f4fe90, rv=rv@entry=0x0) at src/http/modules/perl/ngx_http_perl_module.c:710
sv = <optimized out>
n = <optimized out>
status = 0
line = <optimized out>
err = <optimized out>
len = 124
n_a = 15
i = <optimized out>
c = 0x24ddeb0
sp = 0x2355608
#6 0x00000000004f4c35 in ngx_http_perl_handle_request (r=0x1be3ba0) at src/http/modules/perl/ngx_http_perl_module.c:223
my_perl = 0x176df30
sub = <optimized out>
rc = <optimized out>
uri = {len = 29245296, data = 0x1be3ba0 "HTTP"}
args = {len = 38851902, data = 0x2d97e1a "pubs/share/book/cover/"}
handler = <optimized out>
ctx = 0x1be4a78
plcf = <optimized out>
pmcf = 0x25985a8
---Type <return> to continue, or q <return> to quit---
#7 0x00000000004f4e38 in ngx_http_perl_handler (r=<optimized out>) at src/http/modules/perl/ngx_http_perl_module.c:174
No locals.
#8 0x000000000049acaf in ngx_http_core_content_phase (r=0x1be3ba0, ph=<optimized out>) at src/http/ngx_http_core_module.c:1169
root = 29244320
rc = <optimized out>
path = {len = 47811856,
data = 0x499a33 <ngx_http_core_generic_phase+35> "H\205\300tPH\203\370\373tbH\211\302\061\355H\203\342\375H\203\372\374t\vH\211\306H\211\337\350xd"}
#9 0x00000000004953c5 in ngx_http_core_run_phases (r=0x1be3ba0) at src/http/ngx_http_core_module.c:858
rc = <optimized out>
ph = 0x2d98bf0
cmcf = <optimized out>
#10 0x00000000004d6da8 in ngx_http_v2_run_request (r=0x1be3ba0) at src/http/v2/ngx_http_v2.c:3789
fc = 0x24ddeb0
#11 0x00000000004d6e55 in ngx_http_v2_state_header_complete (h2c=0x23acf40,
pos=0x2512965 "f\242\201\260\332\340S\372\344j\244?\204)\247z\201\002\340\373S\221\252q\257\265<\270\327\366\244\065\327Ay\026<\306K\r\262\352츧\365\233\036\375\031\376\224\240\335J\246\"\223\251\377\265/Oa\351+\r\211p.'Zep\205\305\067\016Q\330f\033e\325\331qL\022LV\002\332\341l\016\063s\243\235)\255\027\030bk\aR\027\235\005^\313X\244\326X{\030\256\330\320\302'\035\205`N8\363O:\027\177@\223\230\251!\352IjL\245\032m\260\250^J*\032\347\262o\001\061Q\204\262ն\360P\215\233٫\372RB\313@\322_\245#\263`\377\206\001\212a\301\212\020\256%\335q\260\001\326^\n\341m\260\272", <incomplete sequence \363>...,
end=0x2512965 "f\242\201\260\332\340S\372\344j\244?\204)\247z\201\002\340\373S\221\252q\257\265<\270\327\366\244\065\327Ay\026<\306K\r\262\352츧\365\233\036\375\031\376\224\240\335J\246\"\223\251\377\265/Oa\351+\r\211p.'Zep\205\305\067\016Q\330f\033e\325\331qL\022LV\002\332\341l\016\063s\243\235)\255\027\030bk\aR\027\235\005^\313X\244\326X{\030\256\330\320\302'\035\205`N8\363O:\027\177@\223\230\251!\352IjL\245\032m\260\250^J*\032\347\262o\001\061Q\204\262ն\360P\215\233٫\372RB\313@\322_\245#\263`\377\206\001\212a\301\212\020\256%\335q\260\001\326^\n\341m\260\272", <incomplete sequence \363>...) at src/http/v2/ngx_http_v2.c:1704
stream = <optimized out>
end = 0x2512965 "f\242\201\260\332\340S\372\344j\244?\204)\247z\201\002\340\373S\221\252q\257\265<\270\327\366\244\065\327Ay\026<\306K\r\262\352츧\365\233\036\375\031\376\224\240\335J\246\"\223\251\377\265/Oa\351+\r\211p.'Zep\205\305\067\016Q\330f\033e\325\331qL\022LV\002\332\341l\016\063s\243\235)\255\027\030bk\aR\027\235\005^\313X\244\326X{\030\256\330\320\302'\035\205`N8\363O:\027\177@\223\230\251!\352IjL\245\032m\260\250^J*\032\347\262o\001\061Q\204\262ն\360P\215\233٫\372RB\313@\322_\245#\263`\377\206\001\212a\301\212\020\256%\335q\260\001\326^\n\341m\260\272", <incomplete sequence \363>...
pos = 0x2512965 "f\242\201\260\332\340S\372\344j\244?\204)\247z\201\002\340\373S\221\252q\257\265<\270\327\366\244\065\327Ay\026<\306K\r\262\352츧\365\233\036\375\031\376\224\240\335J\246\"\223\251\377\265/Oa\351+\r\211p.'Zep\205\305\067\016Q\330f\033e\325\331qL\022LV\002\332\341l\016\063s\243\235)\255\027\030bk\aR\027\235\005^\313X\244\326X{\030\256\330\320\302'\035\205`N8\363O:\027\177@\223\230\251!\352IjL\245\032m\260\250^J*\032\347\262o\001\061Q\204\262ն\360P\215\233٫\372RB\313@\322_\245#\263`\377\206\001\212a\301\212\020\256%\335q\260\001\326^\n\341m\260\272", <incomplete sequence \363>...
h2c = 0x23acf40
#12 0x00000000004d7fff in ngx_http_v2_state_header_block (h2c=0x23acf40,
pos=0x2512965 "f\242\201\260\332\340S\372\344j\244?\204)\247z\201\002\340\373S\221\252q\257\265<\270\327\366\244\065\327Ay\026<\306K\r\262\352츧\365\233\036\375\031\376\224\240\335J\246\"\223\251\377\265/Oa\351+\r\211p.'Zep\205\305\067\016Q\330f\033e\325\331qL\022LV\002\332\341l\016\063s\243\235)\255\027\030bk\aR\027\235\005^\313X\244\326X{\030\256\330\320\302'\035\205`N8\363O:\027\177@\223\230\251!\352IjL\245\032m\260\250^J*\032\347\262o\001\061Q\204\262ն\360P\215\233٫\372RB\313@\322_\245#\263`\377\206\001\212a\301\212\020\256%\335q\260\001\326^\n\341m\260\272", <incomplete sequence \363>...,
end=0x2512965 "f\242\201\260\332\340S\372\344j\244?\204)\247z\201\002\340\373S\221\252q\257\265<\270\327\366\244\065\327Ay\026<\306K\r\262\352츧\365\233\036\375\031\376\224\240\335J\246\"\223\251\377\265/Oa\351+\r\211p.'Zep\205\305\067\016Q\330f\033e\325\331qL\022LV\002\332\341l\016\063s\243\235)\255\027\030bk\aR\027\235\005^\313X\244\326X{\030\256\330\320\302'\035\205`N8\363O:\027\177@\223\230\251!\352IjL\245\032m\260\250^J*\032\347\262o\001\061Q\204\262ն\360P\215\233٫\372RB\313@\322_\245#\263`\377\206\001\212a\301\212\020\256%\335q\260\001\326^\n\341m\260\272", <incomplete sequence \363>...) at src/http/v2/ngx_http_v2.c:1273
ch = <optimized out>
---Type <return> to continue, or q <return> to quit---
value = <optimized out>
indexed = 1
size_update = 0
prefix = 127
#13 0x00000000004d58a0 in ngx_http_v2_read_handler (rev=0x2434070) at src/http/v2/ngx_http_v2.c:413
p = <optimized out>
end = 0x2512965 "f\242\201\260\332\340S\372\344j\244?\204)\247z\201\002\340\373S\221\252q\257\265<\270\327\366\244\065\327Ay\026<\306K\r\262\352츧\365\233\036\375\031\376\224\240\335J\246\"\223\251\377\265/Oa\351+\r\211p.'Zep\205\305\067\016Q\330f\033e\325\331qL\022LV\002\332\341l\016\063s\243\235)\255\027\030bk\aR\027\235\005^\313X\244\326X{\030\256\330\320\302'\035\205`N8\363O:\027\177@\223\230\251!\352IjL\245\032m\260\250^J*\032\347\262o\001\061Q\204\262ն\360P\215\233٫\372RB\313@\322_\245#\263`\377\206\001\212a\301\212\020\256%\335q\260\001\326^\n\341m\260\272", <incomplete sequence \363>...
n = <optimized out>
c = 0x27c4840
h2mcf = 0x2597b30
h2c = 0x23acf40
#14 0x0000000000487329 in ngx_epoll_process_events (cycle=0x25952e0, timer=<optimized out>, flags=<optimized out>)
at src/event/modules/ngx_epoll_module.c:902
events = <optimized out>
revents = 1
instance = <optimized out>
i = 0
level = <optimized out>
err = <optimized out>
rev = 0x2434070
wev = <optimized out>
queue = <optimized out>
c = 0x27c4840
#15 0x000000000047c3f7 in ngx_process_events_and_timers (cycle=cycle@entry=0x25952e0) at src/event/ngx_event.c:242
flags = <optimized out>
timer = <optimized out>
delta = 4999262025
#16 0x0000000000485015 in ngx_worker_process_cycle (cycle=cycle@entry=0x25952e0, data=data@entry=0xe)
at src/os/unix/ngx_process_cycle.c:750
worker = 14
#17 0x000000000048363c in ngx_spawn_process (cycle=cycle@entry=0x25952e0, proc=proc@entry=0x484fd0 <ngx_worker_process_cycle>,
data=data@entry=0xe, name=name@entry=0x6e780e "worker process", respawn=respawn@entry=-4) at src/os/unix/ngx_process.c:199
on = 1
pid = 0
s = 14
#18 0x00000000004847d4 in ngx_start_worker_processes (cycle=cycle@entry=0x25952e0, n=40, type=type@entry=-4)
at src/os/unix/ngx_process_cycle.c:359
i = 14
ch = {command = 1, pid = 22727, slot = 13, fd = 48}
#19 0x0000000000485ebc in ngx_master_process_cycle (cycle=0x25952e0, cycle@entry=0x1725d10) at src/os/unix/ngx_process_cycle.c:244
title = <optimized out>
p = <optimized out>
size = <optimized out>
i = <optimized out>
n = <optimized out>
---Type <return> to continue, or q <return> to quit---
sigio = 0
set = {__val = {0 <repeats 16 times>}}
itv = {it_interval = {tv_sec = 0, tv_usec = 0}, it_value = {tv_sec = 0, tv_usec = 0}}
live = <optimized out>
delay = 0
ls = <optimized out>
ccf = 0x2596770
#20 0x000000000045acd2 in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:382
b = <optimized out>
log = 0x9f8fc0 <ngx_log>
i = <optimized out>
cycle = 0x1725d10
init_cycle = {conf_ctx = 0x0, pool = 0x1724f70, log = 0x9f8fc0 <ngx_log>, new_log = {log_level = 0, file = 0x0, connection = 0,
disk_full_time = 0, handler = 0x0, data = 0x0, writer = 0x0, wdata = 0x0, action = 0x0, next = 0x0}, log_use_stderr = 0,
files = 0x0, free_connections = 0x0, free_connection_n = 0, modules = 0x0, modules_n = 0, modules_used = 0,
reusable_connections_queue = {prev = 0x0, next = 0x0}, reusable_connections_n = 0, listening = {elts = 0x0, nelts = 0, size = 0,
nalloc = 0, pool = 0x0}, paths = {elts = 0x0, nelts = 0, size = 0, nalloc = 0, pool = 0x0}, config_dump = {elts = 0x0,
nelts = 0, size = 0, nalloc = 0, pool = 0x0}, config_dump_rbtree = {root = 0x0, sentinel = 0x0, insert = 0x0},
config_dump_sentinel = {key = 0, left = 0x0, right = 0x0, parent = 0x0, color = 0 '\000', data = 0 '\000'}, open_files = {
last = 0x0, part = {elts = 0x0, nelts = 0, next = 0x0}, size = 0, nalloc = 0, pool = 0x0}, shared_memory = {last = 0x0,
part = {elts = 0x0, nelts = 0, next = 0x0}, size = 0, nalloc = 0, pool = 0x0}, connection_n = 0, files_n = 0,
connections = 0x0, read_events = 0x0, write_events = 0x0, old_cycle = 0x0, conf_file = {len = 21,
data = 0x6e220e "/etc/nginx/nginx.conf"}, conf_param = {len = 0, data = 0x0}, conf_prefix = {len = 11,
data = 0x6e220e "/etc/nginx/nginx.conf"}, prefix = {len = 17, data = 0x6e21fc "/usr/share/nginx/"}, lock_file = {len = 0,
data = 0x0}, hostname = {len = 0, data = 0x0}}
cd = <optimized out>
ccf = <optimized out>
(gdb)
(gdb) set $log = ngx_cycle->log
(gdb)
(gdb) while $log->writer != ngx_log_memory_writer
> set $log = $log->next
>end
(gdb)
(gdb) set $buf = (ngx_log_memory_buf_t *) $log->wdata
(gdb) dump binary memory debug_log.txt $buf->start $buf->end
(gdb)
additional query:
(gdb) fr 0
#0 ngx_http_perl_output (r=r@entry=0x1be3ba0, b=b@entry=0x1d3cd30) at nginx.xs:78
78 if (ctx->ssi) {
(gdb) p *r
$1 = {signature = 1347703880, connection = 0x24ddeb0, ctx = 0x1be45e8, main_conf = 0x2596cf8, srv_conf = 0x1ecfd38, loc_conf = 0x1f4f1e0,
read_event_handler = 0x49f140 <ngx_http_block_reading>, write_event_handler = 0x49cd70 <ngx_http_request_empty_handler>, cache = 0x0,
upstream = 0x0, upstream_states = 0x0, pool = 0x1be3b50, header_in = 0x1be4780, headers_in = {headers = {last = 0x1be3c10, part = {
elts = 0x1d3c4a0, nelts = 10, next = 0x0}, size = 48, nalloc = 20, pool = 0x1be3b50}, host = 0x1d3c4a0, connection = 0x0,
if_modified_since = 0x0, if_unmodified_since = 0x1d3c4d0, if_match = 0x1d3c500, if_none_match = 0x0, user_agent = 0x1d3c590,
referer = 0x1d3c5c0, content_length = 0x0, content_range = 0x0, content_type = 0x0, range = 0x1d3c530, if_range = 0x0,
transfer_encoding = 0x0, te = 0x0, expect = 0x0, upgrade = 0x0, accept_encoding = 0x1d3c620, via = 0x0, authorization = 0x0,
keep_alive = 0x0, x_forwarded_for = {elts = 0x0, nelts = 0, size = 0, nalloc = 0, pool = 0x0}, x_real_ip = 0x0, accept = 0x1d3c560,
accept_language = 0x1d3c5f0, user = {len = 0, data = 0x0}, passwd = {len = 0, data = 0x0}, cookies = {elts = 0x1be4a30, nelts = 1,
size = 8, nalloc = 1, pool = 0x1be3b50}, server = {len = 12, data = 0x250d55e "grans.hse.ru"}, content_length_n = -1,
keep_alive_n = -1, connection_type = 1, chunked = 0, msie = 0, msie6 = 0, opera = 0, gecko = 0, chrome = 1, safari = 0,
konqueror = 0}, headers_out = {headers = {last = 0x1be3da0, part = {elts = 0x1be4168, nelts = 0, next = 0x0}, size = 48, nalloc = 20,
pool = 0x1be3b50}, trailers = {last = 0x1be3dd8, part = {elts = 0x1be4528, nelts = 0, next = 0x0}, size = 48, nalloc = 4,
pool = 0x1be3b50}, status = 412, status_line = {len = 0, data = 0x0}, server = 0x0, date = 0x0, content_length = 0x0,
content_encoding = 0x0, location = 0x0, refresh = 0x0, last_modified = 0x0, content_range = 0x0, accept_ranges = 0x0,
www_authenticate = 0x0, expires = 0x0, etag = 0x0, override_charset = 0x0, content_type_len = 9, content_type = {len = 24,
data = 0x1d3c9f2 "text/html; charset=utf-8 "}, charset = {len = 5, data = 0x172823f "utf-8"},
content_type_lowcase = 0x1be4b3c "text/htmlser-agentie\020\020", content_type_hash = 101824002410317, cache_control = {elts = 0x0,
nelts = 0, size = 0, nalloc = 0, pool = 0x0}, link = {elts = 0x0, nelts = 0, size = 0, nalloc = 0, pool = 0x0},
content_length_n = 568, content_offset = 0, date_time = 0, last_modified_time = -1}, request_body = 0x0, lingering_time = 0,
start_sec = 1559742175, start_msec = 114, method = 2, http_version = 2000, request_line = {len = 41,
data = 0x1be48a0 "GET /mirror/pubs/share/266848717 HTTP/2.0"}, uri = {len = 28, data = 0x250d536 "/mirror/pubs/share/266848717"},
args = {len = 0, data = 0x0}, exten = {len = 0, data = 0x0}, unparsed_uri = {len = 28, data = 0x250d536 "/mirror/pubs/share/266848717"},
method_name = {len = 3, data = 0x6ea1e4 "GET"}, http_protocol = {len = 8, data = 0x6f1bf8 "HTTP/2.0"}, schema = {len = 5,
data = 0x6edcfe "https"}, out = 0x0, main = 0x1be3ba0, parent = 0x0, postponed = 0x0, post_subrequest = 0x0, posted_requests = 0x0,
phase_handler = 13, content_handler = 0x4f4e20 <ngx_http_perl_handler>, access_code = 0, variables = 0x1d3c030, ncaptures = 2,
captures = 0x1be4a38, captures_data = 0x250d536 "/mirror/pubs/share/266848717", limit_rate = 0, limit_rate_after = 0, header_size = 78,
request_length = 60, err_status = 412, http_connection = 0x24e4760, stream = 0x1be47e0,
log_handler = 0x49d350 <ngx_http_log_error_handler>, cleanup = 0x1d3cb18, count = 2, subrequests = 51, blocked = 0, aio = 0,
http_state = 2, complex_uri = 0, quoted_uri = 0, plus_in_uri = 0, space_in_uri = 0, invalid_header = 0, add_uri_to_alias = 0,
valid_location = 1, valid_unparsed_uri = 1, uri_changed = 0, uri_changes = 11, request_body_in_single_buf = 0,
request_body_in_file_only = 0, request_body_in_persistent_file = 0, request_body_in_clean_file = 0, request_body_file_group_access = 0,
request_body_file_log_level = 5, request_body_no_buffering = 0, subrequest_in_memory = 0, waited = 0, cached = 0, gzip_tested = 0,
gzip_ok = 0, gzip_vary = 0, realloc_captures = 0, proxy = 0, bypass_cache = 0, no_cache = 0, limit_conn_set = 0, limit_req_set = 0,
pipeline = 0, chunked = 0, header_only = 0, expect_trailers = 0, keepalive = 0, lingering_close = 0, discard_body = 0, reading_body = 0,
internal = 0, error_page = 1, filter_finalize = 1, post_action = 0, request_complete = 0, request_output = 1, header_sent = 1,
expect_tested = 1, root_tested = 0, done = 0, logged = 0, buffered = 0, main_filter_need_in_memory = 1, filter_need_in_memory = 0,
filter_need_temporary = 0, preserve_body = 0, allow_ranges = 0, subrequest_ranges = 0, single_range = 0, disable_not_modified = 0,
stat_reading = 0, stat_writing = 1, stat_processing = 0, background = 0, health_check = 0, state = 0, header_hash = 0,
lowcase_index = 0, lowcase_header = '\000' <repeats 31 times>, header_name_start = 0x0, header_name_end = 0x0, header_start = 0x0,
header_end = 0x0, uri_start = 0x250d536 "/mirror/pubs/share/266848717", uri_end = 0x250d552 "", uri_ext = 0x0, args_start = 0x0,
request_start = 0x0, request_end = 0x0, method_end = 0x0, schema_start = 0x0, schema_end = 0x0, host_start = 0x0, host_end = 0x0,
port_start = 0x0, port_end = 0x0, http_minor = 0, http_major = 0}
(gdb) p *r->connection
$2 = {data = 0x1be3ba0, read = 0x24ddfa8, write = 0x24de008, fd = 8, recv = 0x48cc20 <ngx_ssl_recv>, send = 0x48d030 <ngx_ssl_write>,
recv_chain = 0x48cf60 <ngx_ssl_recv_chain>, send_chain = 0x4c1f30 <ngx_http_v2_send_chain>, listening = 0x2595930, sent = 646,
log = 0x24de068, pool = 0x24e46a0, type = 1, sockaddr = 0x24e46f0, socklen = 16, addr_text = {len = 13,
data = 0x24e4750 "79.98.215.226"}, proxy_protocol_addr = {len = 0, data = 0x0}, proxy_protocol_port = 0, ssl = 0x24e47b8, udp = 0x0,
local_sockaddr = 0x2d99ba8, local_socklen = 16, buffer = 0x0, queue = {prev = 0x0, next = 0x0}, number = 92005, requests = 2,
buffered = 0, log_error = 2, timedout = 0, error = 0, destroyed = 0, idle = 1, reusable = 0, close = 0, shared = 0, sendfile = 1,
sndlowat = 1, tcp_nodelay = 2, tcp_nopush = 0, need_last_buf = 1, sendfile_task = 0x0}
(gdb) p r->connection->number
$3 = 92005
access log:
79.98.215.226 - - [05/Jun/2019:16:42:55 +0300] "GET /mirror/pubs/share/266848717 HTTP/2.0" 206 3990 "https://grans.hse.ru/mirror/pubs/share/266848717" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 Edge/15.15063" "-" "ticket=-,tracking=CgAGP1zlAz55mT15AyNYAg==,_lang=-" "-" "-" "[cs=-, request_time=0.000, upstream_response_time=-, upstream_response_length=-, upstream=-//-]" "[grans.hse.ru]" 79.98.215.226 - - [05/Jun/2019:16:42:55 +0300] "GET /mirror/pubs/share/266848717 HTTP/2.0" 206 233366 "https://grans.hse.ru/mirror/pubs/share/266848717" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 Edge/15.15063" "-" "ticket=-,tracking=CgAGP1zlAz55mT15AyNYAg==,_lang=-" "-" "-" "[cs=-, request_time=0.013, upstream_response_time=-, upstream_response_length=-, upstream=-//-]" "[grans.hse.ru]" 79.98.215.226 - - [05/Jun/2019:16:42:55 +0300] "GET /mirror/pubs/share/266848717 HTTP/2.0" 206 3990 "https://grans.hse.ru/mirror/pubs/share/266848717" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 Edge/15.15063" "-" "ticket=-,tracking=CgAGP1zlAz55mT15AyNYAg==,_lang=-" "-" "-" "[cs=-, request_time=0.000, upstream_response_time=-, upstream_response_length=-, upstream=-//-]" "[grans.hse.ru]" 79.98.215.226 - - [05/Jun/2019:16:42:55 +0300] "GET /mirror/pubs/share/266848717 HTTP/2.0" 206 8086 "https://grans.hse.ru/mirror/pubs/share/266848717" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 Edge/15.15063" "-" "ticket=-,tracking=CgAGP1zlAz55mT15AyNYAg==,_lang=-" "-" "-" "[cs=-, request_time=0.000, upstream_response_time=-, upstream_response_length=-, upstream=-//-]" "[grans.hse.ru]" 79.98.215.226 - - [05/Jun/2019:16:42:56 +0300] "GET /mirror/pubs/share/266848717 HTTP/2.0" 206 233366 "https://grans.hse.ru/mirror/pubs/share/266848717" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 Edge/15.15063" "-" "ticket=-,tracking=CgAGP1zlAz55mT15AyNYAg==,_lang=-" "-" "-" "[cs=-, request_time=0.013, upstream_response_time=-, upstream_response_length=-, upstream=-//-]" "[grans.hse.ru]" 79.98.215.226 - - [05/Jun/2019:16:42:56 +0300] "GET /mirror/pubs/share/266848717 HTTP/2.0" 206 20374 "https://grans.hse.ru/mirror/pubs/share/266848717" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 Edge/15.15063" "-" "ticket=-,tracking=CgAGP1zlAz55mT15AyNYAg==,_lang=-" "-" "-" "[cs=-, request_time=0.000, upstream_response_time=-, upstream_response_length=-, upstream=-//-]" "[grans.hse.ru]" 79.98.215.226 - - [05/Jun/2019:16:42:56 +0300] "GET /mirror/pubs/share/266848717 HTTP/2.0" 206 229270 "https://grans.hse.ru/mirror/pubs/share/266848717" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 Edge/15.15063" "-" "ticket=-,tracking=CgAGP1zlAz55mT15AyNYAg==,_lang=-" "-" "-" "[cs=-, request_time=0.012, upstream_response_time=-, upstream_response_length=-, upstream=-//-]" "[grans.hse.ru]" 79.98.215.226 - - [05/Jun/2019:16:42:57 +0300] "GET /mirror/pubs/share/266848717 HTTP/2.0" 206 233366 "https://grans.hse.ru/mirror/pubs/share/266848717" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 Edge/15.15063" "-" "ticket=-,tracking=CgAGP1zlAz55mT15AyNYAg==,_lang=-" "-" "-" "[cs=-, request_time=0.036, upstream_response_time=-, upstream_response_length=-, upstream=-//-]" "[grans.hse.ru]" 79.98.215.226 - - [05/Jun/2019:16:42:57 +0300] "GET /mirror/pubs/share/266848717 HTTP/2.0" 206 3990 "https://grans.hse.ru/mirror/pubs/share/266848717" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 Edge/15.15063" "-" "ticket=-,tracking=CgAGP1zlAz55mT15AyNYAg==,_lang=-" "-" "-" "[cs=-, request_time=0.000, upstream_response_time=-, upstream_response_length=-, upstream=-//-]" "[grans.hse.ru]"
debug data:
NXD1.HK0/mif: /tmp # grep 92005 debug_log.txt 2019/06/05 16:42:55 [debug] 22728#22728: *92005 accept: 79.98.215.226:55466 fd:8 2019/06/05 16:42:55 [debug] 22728#22728: *92005 event timer add: 8: 60000:4999322013 2019/06/05 16:42:55 [debug] 22728#22728: *92005 reusable connection: 1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 epoll add event: fd:8 op:1 ev:80002001 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http check ssl handshake 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http recv(): 1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 https ssl handshake: 0x16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 tcp_nodelay 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL server name: "grans.hse.ru" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL ALPN supported by client: h2 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL ALPN supported by client: http/1.1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL ALPN selected: h2 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_do_handshake: -1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_get_error: 2 2019/06/05 16:42:55 [debug] 22728#22728: *92005 reusable connection: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL handshake handler: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_do_handshake: 1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL: TLSv1.2, cipher: "ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(128) Mac=AEAD" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL reused session 2019/06/05 16:42:55 [debug] 22728#22728: *92005 init http2 connection 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 00000000023ACF20:512 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 0000000001BE3B50:4096 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 add cleanup: 00000000024E4830 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 000000000250DBF0:512 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 send SETTINGS frame 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 send WINDOW_UPDATE frame sid:0, window:2147418112 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 read handler 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_read: -1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_get_error: 2 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame out: 0000000001BE3C58 sid:0 bl:0 len:4 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame out: 0000000001BE3BA0 sid:0 bl:0 len:18 2019/06/05 16:42:55 [debug] 22728#22728: *92005 malloc: 000000000213C0E0:16384 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL buf copy: 27 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL buf copy: 13 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL to write: 40 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_write: 40 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame sent: 0000000001BE3BA0 sid:0 bl:0 len:18 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame sent: 0000000001BE3C58 sid:0 bl:0 len:4 2019/06/05 16:42:55 [debug] 22728#22728: *92005 free: 0000000001BE3B50, unused: 3656 2019/06/05 16:42:55 [debug] 22728#22728: *92005 free: 000000000213C0E0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 reusable connection: 1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 event timer del: 8: 4999322013 2019/06/05 16:42:55 [debug] 22728#22728: *92005 event timer add: 8: 180000:4999442017 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 idle handler 2019/06/05 16:42:55 [debug] 22728#22728: *92005 reusable connection: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 0000000001BE3B50:4096 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 read handler 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_read: 58 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_read: -1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_get_error: 2 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 preface verified 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame type:4 f:0 l:12 sid:0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 SETTINGS frame 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 setting 3:1024 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 setting 4:10485760 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame complete pos:000000000251294D end:000000000251295A 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame type:8 f:0 l:4 sid:0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 WINDOW_UPDATE frame sid:0 window:10420225 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame complete pos:000000000251295A end:000000000251295A 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame out: 0000000001BE3BA0 sid:0 bl:0 len:0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 malloc: 000000000213C0E0:16384 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL buf copy: 9 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL to write: 9 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_write: 9 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame sent: 0000000001BE3BA0 sid:0 bl:0 len:0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 free: 0000000001BE3B50, unused: 3840 2019/06/05 16:42:55 [debug] 22728#22728: *92005 free: 000000000213C0E0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 reusable connection: 1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 event timer: 8, old: 4999442017, new: 4999442017 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 idle handler 2019/06/05 16:42:55 [debug] 22728#22728: *92005 reusable connection: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 0000000001BE3B50:4096 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 read handler 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_read: 511 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_read: -1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_get_error: 2 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame type:1 f:5 l:502 sid:1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 HEADERS frame sid:1 depends on 0 excl:0 weight:16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 000000000250D4E0:1024 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 00000000024DDE60:4096 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 0000000001C83DD0:4096 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 malloc: 000000000213C0E0:16384 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed header: 2 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: ":method: GET" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed name: 4 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 encoded string, len:20 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table add: ":path: /mirror/pubs/share/266848717" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 malloc: 0000000002509010:512 2019/06/05 16:42:55 [debug] 22728#22728: *92005 malloc: 0000000001C8D000:4096 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table account: 65 free:4096 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http uri: "/mirror/pubs/share/266848717" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http args: "" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http exten: "" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: ":path: /mirror/pubs/share/266848717" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed name: 1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 encoded string, len:9 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table add: ":authority: grans.hse.ru" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table account: 54 free:4031 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: ":authority: grans.hse.ru" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed header: 7 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: ":scheme: https" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed name: 50 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 encoded string, len:14 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table add: "range: bytes=229376-233365" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table account: 56 free:3977 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "range: bytes=229376-233365" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed name: 19 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 raw string, len:3 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table add: "accept: */*" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table account: 41 free:3921 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 0000000002509760:512 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "accept: */*" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed name: 58 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 encoded string, len:98 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table add: "user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 Edge/15.15063" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table account: 171 free:3880 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 Edge/15.15063" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed name: 51 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 encoded string, len:35 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table add: "referer: https://grans.hse.ru/mirror/pubs/share/266848717" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table account: 87 free:3709 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "referer: https://grans.hse.ru/mirror/pubs/share/266848717" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 encoded string, len:19 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 raw string, len:1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table add: "getcontentfeatures.dlna.org: 1" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table account: 60 free:3622 2019/06/05 16:42:55 [info] 22728#22728: *92005 client sent invalid header: "getcontentfeatures.dlna.org" while reading client request headers, client: 79.98.215.226, server: foresight.hse.ru, host: "grans.hse.ru", referrer: "https://grans.hse.ru/mirror/pubs/share/266848717" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed name: 17 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 encoded string, len:4 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table add: "accept-language: ru-RU" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table account: 52 free:3562 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "accept-language: ru-RU" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed name: 16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 encoded string, len:13 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table add: "accept-encoding: gzip, deflate, br" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table account: 64 free:3510 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "accept-encoding: gzip, deflate, br" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed name: 32 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 encoded string, len:261 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table add: "cookie: _ga=…" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table account: 394 free:3446 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "cookie: _ga=…" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 request line: "GET /mirror/pubs/share/266848717 HTTP/2.0" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 generic phase: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 rewrite phase: 1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "images/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "n/stat/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "live/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "n/edu/courses/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "n/api" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "mirror/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "pubs/lib/js/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "pubs/share/direct/thumb/cover/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "pubs/share/cover/thumb/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "pubs/share/book/cover/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "^/n/exp/widgets/widgetPassExpressPoll/\d+\.js" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "package\.json$" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "^/n/stat/widget_pass_express_poll/element-.*$" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "\.(msn|php)$" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "/\.(hta|hg|git)" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "(apple-touch-icon-precomposed|apple-touch-icon)\.png$" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "^/en(/f/src/.*)" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "^/f/src/\w+/css/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "^/css/bootstrap3/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "^/pubs/share/(folder/\w+/)?\d+$" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "^/mirror/pubs/share/(folder/\w+/)?\d+$" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 using configuration "^/mirror/pubs/share/(folder/\w+/)?\d+$" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http cl:-1 max:2097152000 2019/06/05 16:42:55 [debug] 22728#22728: *92005 rewrite phase: 3 2019/06/05 16:42:55 [debug] 22728#22728: *92005 post rewrite phase: 4 2019/06/05 16:42:55 [debug] 22728#22728: *92005 generic phase: 5 2019/06/05 16:42:55 [debug] 22728#22728: *92005 generic phase: 6 2019/06/05 16:42:55 [debug] 22728#22728: *92005 generic phase: 7 2019/06/05 16:42:55 [debug] 22728#22728: *92005 access phase: 8 2019/06/05 16:42:55 [debug] 22728#22728: *92005 access phase: 9 2019/06/05 16:42:55 [debug] 22728#22728: *92005 post access phase: 10 2019/06/05 16:42:55 [debug] 22728#22728: *92005 generic phase: 11 2019/06/05 16:42:55 [debug] 22728#22728: *92005 generic phase: 12 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl handler 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 08024404 "ETag" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 00044404 "W/"266848717"" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 08024404 "Last-Modified" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 00044404 "Sat, 27 Apr 2019 04:39:57 GMT" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 08024404 "X-Ireland" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 00024404 "Hse::Nginx::FileAccessor, file=266848717" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 08024404 "Content-Disposition" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 00024404 "filename*=UTF-8''%D0%A0%D0%B0%D1%81%D0%BF%D0%B8%D1%81%D0%B0%D0%BD%D0%B8%D0%B5%20I%20%D0%BC%D0%BE%D0%B4%D1%83%D0%BB%D1%8C%20%D0%A4%D0%98%D0%9D%D0%90%D0%9B.pdf" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 08024404 "Content-Length" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 00045505 "233366" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 00004404 "application/pdf" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http map started 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http map: "" "" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http script var: "" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 parse header: "cookie: _ga=…" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 uid cookie: "…==" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 uid: 3F06000A3E03E55C793D997902582303 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header filter 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 push resources 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: ":status: 206" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "server: nginx" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "date: Wed, 05 Jun 2019 13:42:55 GMT" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "content-type: application/pdf" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "content-length: 3990" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "etag: W/"266848717"" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "last-modified: Sat, 27 Apr 2019 04:39:57 GMT" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "x-ireland: Hse::Nginx::FileAccessor, file=266848717" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "content-disposition: filename*=UTF-8''%D0%A0%D0%B0%D1%81%D0%BF%D0%B8%D1%81%D0%B0%D0%BD%D0%B8%D0%B5%20I%20%D0%BC%D0%BE%D0%B4%D1%83%D0%BB%D1%8C%20%D0%A4%D0%98%D0%9D%D0%90%D0%9B.pdf" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "expires: Wed, 05 Jun 2019 15:42:55 GMT" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "cache-control: max-age=7200" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "content-range: bytes 229376-233365/233366" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2:1 create HEADERS frame 0000000001C84AA0: len:360 fin:0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http cleanup add: 0000000001C84BA8 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame out: 0000000001C84AA0 sid:1 bl:1 len:360 2019/06/05 16:42:55 [debug] 22728#22728: *92005 malloc: 0000000002956B90:16384 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL buf copy: 9 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL buf copy: 360 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2:1 HEADERS frame 0000000001C84AA0 was sent 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame sent: 0000000001C84AA0 sid:1 bl:1 len:360 2019/06/05 16:42:55 [debug] 22728#22728: *92005 add cleanup: 0000000001C84D78 2019/06/05 16:42:55 [debug] 22728#22728: *92005 malloc: 0000000002C6C570:144 2019/06/05 16:42:55 [debug] 22728#22728: *92005 malloc: 0000000002C2B810:125 2019/06/05 16:42:55 [debug] 22728#22728: *92005 cached open file: /some/path/data/2019/04/27/1556339997/266848717/somefile.pdf, fd:61, c:1, e:0, u:1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http output filter "/mirror/pubs/share/266848717?" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http range body buf: 0-233366 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http copy filter: "/mirror/pubs/share/266848717?" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 0000000002961BD0:4096 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 0000000001D3C010:4096 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 read: 61, 0000000001D3C030, 3990, 229376 2019/06/05 16:42:55 [debug] 22728#22728: *92005 image filter 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http postpone filter "/mirror/pubs/share/266848717?" 0000000001C84DC0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 write new buf t:1 f:1 0000000001D3C030, pos 0000000001D3C030, size: 3990 file: 229376, size: 3990 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http write filter: l:1 f:0 s:3990 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http write filter limit 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2:1 windows: conn:10485760 stream:10485760 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2:1 create DATA frame 0000000001C84AA0: len:3990 flags:1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame out: 0000000001C84AA0 sid:1 bl:0 len:3990 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL buf copy: 9 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL buf copy: 3990 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL to write: 4368 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_write: 4368 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2:1 DATA frame 0000000001C84AA0 was sent 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame sent: 0000000001C84AA0 sid:1 bl:0 len:3990 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http write filter 0000000000000000 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http copy filter: 0 "/mirror/pubs/share/266848717?" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 call_sv: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl handler done: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http output filter "/mirror/pubs/share/266848717?" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http range body buf: 233366-233366 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http copy filter: "/mirror/pubs/share/266848717?" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 image filter 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http postpone filter "/mirror/pubs/share/266848717?" 00007FFF2F51E040 2019/06/05 16:42:55 [debug] 22728#22728: *92005 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http write filter: l:1 f:0 s:0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http write filter limit 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http write filter 0000000000000000 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http copy filter: 0 "/mirror/pubs/share/266848717?" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http finalize request: 0, "/mirror/pubs/share/266848717?" a:1, c:2 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http request count:2 blk:0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http finalize request: -4, "/mirror/pubs/share/266848717?" a:1, c:1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http request count:1 blk:0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 close stream 1, queued 0, processing 1, pushing 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http close request 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http log handler 2019/06/05 16:42:55 [debug] 22728#22728: *92005 parse header: "cookie: _ga=…" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 parse header: "cookie: _ga=…" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 parse header: "cookie: _ga=…" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 run cleanup: 0000000001C84D78 2019/06/05 16:42:55 [debug] 22728#22728: *92005 close cached open file: /some/path/data/2019/04/27/1556339997/266848717/somefile.pdf, fd:61, c:0, u:1, 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 expire cached open file: /some/path/f/src/global/css/sitemap.css 2019/06/05 16:42:55 [debug] 22728#22728: *92005 close cached open file: /some/path/f/src/global/css/sitemap.css, fd:70, c:0, u:25, 1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 expire cached open file: /some/path/f/src/global/bower_components/tooltipster/dist/css/tooltipster.bundle.min.css 2019/06/05 16:42:55 [debug] 22728#22728: *92005 close cached open file: /some/path/f/src/global/bower_components/tooltipster/dist/css/tooltipster.bundle.min.css, fd:89, c:0, u:2, 1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 free: 000000000213C0E0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 free: 00000000024DDE60, unused: 8 2019/06/05 16:42:55 [debug] 22728#22728: *92005 free: 0000000001C83DD0, unused: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 free: 0000000002961BD0, unused: 3229 2019/06/05 16:42:55 [debug] 22728#22728: *92005 free: 0000000001D3C010, unused: 74 2019/06/05 16:42:55 [debug] 22728#22728: *92005 free: 000000000250D4E0, unused: 176 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame complete pos:0000000002512B1F end:0000000002512B1F 2019/06/05 16:42:55 [debug] 22728#22728: *92005 free: 0000000001BE3B50, unused: 3472 2019/06/05 16:42:55 [debug] 22728#22728: *92005 free: 0000000002956B90 2019/06/05 16:42:55 [debug] 22728#22728: *92005 reusable connection: 1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 event timer: 8, old: 4999442017, new: 4999442017 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 idle handler 2019/06/05 16:42:55 [debug] 22728#22728: *92005 reusable connection: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 00000000024DDE60:4096 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 read handler 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_read: 9 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_read: -1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_get_error: 2 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame type:4 f:1 l:0 sid:0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame complete pos:0000000002512929 end:0000000002512929 2019/06/05 16:42:55 [debug] 22728#22728: *92005 free: 00000000024DDE60, unused: 4016 2019/06/05 16:42:55 [debug] 22728#22728: *92005 reusable connection: 1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 event timer: 8, old: 4999442017, new: 4999442025 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 idle handler 2019/06/05 16:42:55 [debug] 22728#22728: *92005 reusable connection: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 00000000024DDE60:4096 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 read handler 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_read: 69 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_read: -1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_get_error: 2 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame type:1 f:5 l:60 sid:3 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 HEADERS frame sid:3 depends on 0 excl:0 weight:16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 000000000250D4E0:1024 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 0000000001BE3B50:4096 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 posix_memalign: 0000000001D3C010:4096 @16 2019/06/05 16:42:55 [debug] 22728#22728: *92005 malloc: 0000000002956B90:16384 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed header: 2 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: ":method: GET" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed header: 71 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http uri: "/mirror/pubs/share/266848717" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http args: "" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http exten: "" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: ":path: /mirror/pubs/share/266848717" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed header: 70 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: ":authority: grans.hse.ru" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed header: 7 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: ":scheme: https" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed name: 43 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 encoded string, len:22 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table add: "if-unmodified-since: Sat, 27 Apr 2019 04:39:57 GMT" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table account: 80 free:3052 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "if-unmodified-since: Sat, 27 Apr 2019 04:39:57 GMT" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed name: 39 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 encoded string, len:11 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table add: "if-match: W/"266848717"" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table account: 53 free:2972 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "if-match: W/"266848717"" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed name: 50 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 encoded string, len:10 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table add: "range: bytes=0-229375" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 table account: 51 free:2919 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "range: bytes=0-229375" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed header: 71 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "accept: */*" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed header: 70 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 Edge/15.15063" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed header: 69 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "referer: https://grans.hse.ru/mirror/pubs/share/266848717" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed header: 68 2019/06/05 16:42:55 [info] 22728#22728: *92005 client sent invalid header: "getcontentfeatures.dlna.org" while reading client request headers, client: 79.98.215.226, server: foresight.hse.ru, host: "grans.hse.ru", referrer: "https://grans.hse.ru/mirror/pubs/share/266848717" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed header: 67 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "accept-language: ru-RU" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed header: 66 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "accept-encoding: gzip, deflate, br" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 get indexed header: 65 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header: "cookie: _ga=…" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 request line: "GET /mirror/pubs/share/266848717 HTTP/2.0" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 generic phase: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 rewrite phase: 1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "images/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "n/stat/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "live/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "n/edu/courses/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "n/api" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "mirror/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "pubs/lib/js/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "pubs/share/direct/thumb/cover/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "pubs/share/cover/thumb/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: "pubs/share/book/cover/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "^/n/exp/widgets/widgetPassExpressPoll/\d+\.js" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "package\.json$" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "^/n/stat/widget_pass_express_poll/element-.*$" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "\.(msn|php)$" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "/\.(hta|hg|git)" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "(apple-touch-icon-precomposed|apple-touch-icon)\.png$" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "^/en(/f/src/.*)" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "^/f/src/\w+/css/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "^/css/bootstrap3/" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "^/pubs/share/(folder/\w+/)?\d+$" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 test location: ~ "^/mirror/pubs/share/(folder/\w+/)?\d+$" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 using configuration "^/mirror/pubs/share/(folder/\w+/)?\d+$" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http cl:-1 max:2097152000 2019/06/05 16:42:55 [debug] 22728#22728: *92005 rewrite phase: 3 2019/06/05 16:42:55 [debug] 22728#22728: *92005 post rewrite phase: 4 2019/06/05 16:42:55 [debug] 22728#22728: *92005 generic phase: 5 2019/06/05 16:42:55 [debug] 22728#22728: *92005 generic phase: 6 2019/06/05 16:42:55 [debug] 22728#22728: *92005 generic phase: 7 2019/06/05 16:42:55 [debug] 22728#22728: *92005 access phase: 8 2019/06/05 16:42:55 [debug] 22728#22728: *92005 access phase: 9 2019/06/05 16:42:55 [debug] 22728#22728: *92005 post access phase: 10 2019/06/05 16:42:55 [debug] 22728#22728: *92005 generic phase: 11 2019/06/05 16:42:55 [debug] 22728#22728: *92005 generic phase: 12 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl handler 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 08024404 "ETag" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 00044404 "W/"266848717"" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 08024404 "Last-Modified" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 00044404 "Sat, 27 Apr 2019 04:39:57 GMT" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 08024404 "X-Ireland" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 00024404 "Hse::Nginx::FileAccessor, file=266848717" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 08024404 "Content-Disposition" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 00024404 "filename*=UTF-8''%D0%A0%D0%B0%D1%81%D0%BF%D0%B8%D1%81%D0%B0%D0%BD%D0%B8%D0%B5%20I%20%D0%BC%D0%BE%D0%B4%D1%83%D0%BB%D1%8C%20%D0%A4%D0%98%D0%9D%D0%90%D0%9B.pdf" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 08024404 "Content-Length" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 00045505 "233366" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 perl sv2str: 00004404 "application/pdf" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http special response: 412, "/mirror/pubs/share/266848717?" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http map started 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http map: "" "" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http script var: "" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 parse header: "cookie: _ga=…" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 uid cookie: "CgAGP1zlAz55mT15AyNYAg==" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 uid: 3F06000A3E03E55C793D997902582303 2019/06/05 16:42:55 [debug] 22728#22728: *92005 charset: "" > "utf-8" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 header filter 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 push resources 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: ":status: 412" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "server: nginx" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "date: Wed, 05 Jun 2019 13:42:55 GMT" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "content-type: text/html; charset=utf-8" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 output header: "content-length: 568" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2:3 create HEADERS frame 0000000001D3CA10: len:60 fin:0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http cleanup add: 0000000001D3CB18 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame out: 0000000001D3CA10 sid:3 bl:1 len:60 2019/06/05 16:42:55 [debug] 22728#22728: *92005 malloc: 0000000001A7B5B0:16384 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL buf copy: 9 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL buf copy: 60 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2:3 HEADERS frame 0000000001D3CA10 was sent 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame sent: 0000000001D3CA10 sid:3 bl:1 len:60 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http output filter "/mirror/pubs/share/266848717?" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http copy filter: "/mirror/pubs/share/266848717?" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 image filter 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http postpone filter "/mirror/pubs/share/266848717?" 0000000001D3CCA0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 write new buf t:0 f:0 0000000000000000, pos 00000000009E0BE0, size: 120 file: 0, size: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 write new buf t:0 f:0 0000000000000000, pos 00000000009E1620, size: 46 file: 0, size: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 write new buf t:0 f:0 0000000000000000, pos 00000000009E1480, size: 402 file: 0, size: 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http write filter: l:1 f:0 s:568 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http write filter limit 0 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2:3 windows: conn:10481770 stream:10485760 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2:3 create DATA frame 0000000001D3CA10: len:568 flags:1 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame out: 0000000001D3CA10 sid:3 bl:0 len:568 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL buf copy: 9 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL buf copy: 120 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL buf copy: 46 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL buf copy: 402 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL to write: 646 2019/06/05 16:42:55 [debug] 22728#22728: *92005 SSL_write: 646 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2:3 DATA frame 0000000001D3CA10 was sent 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http2 frame sent: 0000000001D3CA10 sid:3 bl:0 len:568 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http write filter 0000000000000000 2019/06/05 16:42:55 [debug] 22728#22728: *92005 http copy filter: 0 "/mirror/pubs/share/266848717?" 2019/06/05 16:42:55 [debug] 22728#22728: *92005 add cleanup: 0000000001D3CEE8 2019/06/05 16:42:55 [debug] 22728#22728: *92005 cached open file: /some/path/data/2019/04/27/1556339997/266848717/somefile.pdf, fd:61, c:1, e:0, u:2
BTW, 412 code mentioned in debug log… but what doest it mean?
206 – partial content again
comment:13 by , 5 years ago
Thanks for the details provided. As originally suggested, this segmentation fault is due to filter finalization, but I incorrectly assumed that problems can only happen when using error_page 412 - in fact, just triggering 412 is enough. Please try the following patch, it should resolve this particular problem:
# HG changeset patch
# User Maxim Dounin <mdounin@mdounin.ru>
# Date 1559748092 -10800
# Wed Jun 05 18:21:32 2019 +0300
# Node ID 5321e759761045e5966dcc723dea5b0b5aff1611
# Parent d964b0aee8e715bc6df4112b8b6ff23540c00d79
Perl: disabled not_modified filter (ticket #1786).
Embedded perl does not set any request fields needed for conditional
requests processing. Further, filter finalization in the not_modified
filter can cause segmentation faults due to cleared ctx as in
ticket #1786.
Before 5fb1e57c758a (1.7.3) the not_modified filter was implicitly disabled
for perl responses, as r->headers_out.last_modified_time was -1. This
change restores this behaviour by using the explicit r->disable_not_modified
flag.
Note that this patch doesn't try to address perl module robustness against
filter finalization and other errors returned from filter chains. It should
be eventually reworked to handle these cases properly instead of ignoring
errors returned.
diff --git a/src/http/modules/perl/nginx.xs b/src/http/modules/perl/nginx.xs
--- a/src/http/modules/perl/nginx.xs
+++ b/src/http/modules/perl/nginx.xs
@@ -147,6 +147,8 @@ send_http_header(r, ...)
}
}
+ r->disable_not_modified = 1;
+
(void) ngx_http_send_header(r);
comment:14 by , 5 years ago
Thanks!
I applied the path and re-compiled again…
I'll report monitoring results tomorrow.
comment:15 by , 5 years ago
It looks there are no crashes anymore. Great.
Will this patch be included in a stable release?
comment:16 by , 5 years ago
Thanks for testing. It is likely to be committed and will be in the next mainline release. It's likely to be merged into stable branch at some point, though there is no ETA.
Note:
See TracTickets
for help on using tickets.
Please provide full configuration and the Perl code in question.