Opened 5 years ago

Closed 5 years ago

#1786 closed defect (fixed)

Send file from Perl module

Reported by: UncleMiF@… 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 Maxim Dounin)

(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 Maxim Dounin, 5 years ago

Description: modified (diff)

Please provide full configuration and the Perl code in question.

comment:2 by UncleMiF@…, 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…


p.s.

Sorry, Perl code is private, and just uses Postgres with standard DBI; I can't show it here.

Version 1, edited 5 years ago by UncleMiF@… (previous) (next) (diff)

comment:3 by Maxim Dounin, 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.

comment:4 by UncleMiF@…, 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;
 }
}

in reply to:  4 comment:5 by Maxim Dounin, 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 UncleMiF@…, 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 Maxim Dounin, 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.

Last edited 5 years ago by Maxim Dounin (previous) (diff)

comment:8 by UncleMiF@…, 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.

Last edited 5 years ago by UncleMiF@… (previous) (diff)

comment:9 by Maxim Dounin, 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.

in reply to:  9 comment:10 by UncleMiF@…, 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_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.

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 Maxim Dounin, 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 UncleMiF@…, 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 Maxim Dounin, 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 UncleMiF@…, 5 years ago

Thanks!
I applied the path and re-compiled again…
I'll report monitoring results tomorrow.

comment:15 by UncleMiF@…, 5 years ago

It looks there are no crashes anymore. Great.
Will this patch be included in a stable release?

Last edited 5 years ago by UncleMiF@… (previous) (diff)

comment:16 by Maxim Dounin, 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.

comment:17 by Maxim Dounin <mdounin@…>, 5 years ago

In 7516:36c52a0f6ded/nginx:

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 errors instead of ignoring them.

comment:18 by Maxim Dounin, 5 years ago

Resolution: fixed
Status: newclosed

Fix committed.

Note: See TracTickets for help on using tickets.