SSL_write() failed (SSL:) (1: operation not permitted) when serving MP4 over HTTPS

Server NGINX
1

Hi,

I’ve searched the mailing list but haven’t found anything relating to
this
error:, the closest I found: #428 (SPDY and Proxy Cache prematurely closes connections) – nginx -
however that was closed 6 weeks ago and the error I get is with/without
SPDY.

I can’t see whether I have misconfigured something? or it may be a bug.

SPDY error
nginx-error.log
[crit]: *12 SSL_write() failed (SSL:) (1: Operation not permitted) while
processing SPDY, client: 10.0.0.2, server: 0.0.0.0:443)

SSL error (no SPDY)
SSL_write() failed (SSL:) (1: Operation not permitted) while sending mp4
to
client, client: 10.0.0.2, server: dev.test.com, request: “GET
/video/homepage.mp4?start=0 HTTP/1.1”, host: “dev.test.com”, referrer:
“https://dev.test.com/index_test2.php”

Essentially the error arises when serving an MP4 with or without SPDY
over
SSL. N.B. Not an issue over pure HTTP. Essentially the video appears,
plays in a loop when served over HTTP.

Over HTTPS the video playback starts OK but then stops abruptly with an
error.

The Setup
Client <—> Varnish <—> NGINX

*(I have tried disabling Varninsh, no difference)

nginx-debug.log
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 317-325
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 325-345
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 345-381
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 381-389
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 389-576
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 576-592
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 592-624
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 624-640
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 640-652
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 652-668
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 668-5180
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 5180-5196
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 5196-5220
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 5220-5240
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 5240-8076
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 8076-8092
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 8092-8660
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 8660-8668
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body skip
2014/08/12 09:15:10 [debug] 1370#0: *2 http range body buf: 8668-2208998
2014/08/12 09:15:10 [debug] 1370#0: *2 http copy filter:
“/video/homepage.mp4?start=0”
2014/08/12 09:15:10 [debug] 1370#0: *2 malloc: 0000000802239000:32768
2014/08/12 09:15:10 [debug] 1370#0: *2 read: 10, 0000000802239000,
32768,
168
2014/08/12 09:15:10 [debug] 1370#0: *2 http postpone filter
“/video/homepage.mp4?start=0” 00000008021AAA00
2014/08/12 09:15:10 [debug] 1370#0: *2 write new buf t:1 f:1
0000000802239000, pos 0000000802239000, size: 32768 file: 168, size:
32768
2014/08/12 09:15:10 [debug] 1370#0: *2 http write filter: l:0 f:1
s:32768
2014/08/12 09:15:10 [debug] 1370#0: *2 http write filter limit 0
2014/08/12 09:15:10 [debug] 1370#0: *2 spdy:61 create DATA frame
00000008021AFF48: len:8192 flags:0
2014/08/12 09:15:10 [debug] 1370#0: *2 spdy:61 create DATA frame
00000008021AAB48: len:8192 flags:0
2014/08/12 09:15:10 [debug] 1370#0: *2 spdy:61 create DATA frame
00000008021AAC50: len:8192 flags:0
2014/08/12 09:15:10 [debug] 1370#0: *2 spdy:61 create DATA frame
00000008021AAD58: len:8192 flags:0
2014/08/12 09:15:10 [debug] 1370#0: *2 spdy frame out: 00000008021AAD58
sid:61 prio:2 bl:0 len:8192
2014/08/12 09:15:10 [debug] 1370#0: *2 spdy frame out: 00000008021AAC50
sid:61 prio:2 bl:0 len:8192
2014/08/12 09:15:10 [debug] 1370#0: *2 spdy frame out: 00000008021AAB48
sid:61 prio:2 bl:0 len:8192
2014/08/12 09:15:10 [debug] 1370#0: *2 spdy frame out: 00000008021AFF48
sid:61 prio:2 bl:0 len:8192
2014/08/12 09:15:10 [debug] 1370#0: *2 SSL buf copy: 8
2014/08/12 09:15:10 [debug] 1370#0: *2 SSL buf copy: 8192
2014/08/12 09:15:10 [debug] 1370#0: *2 SSL buf copy: 8
2014/08/12 09:15:10 [debug] 1370#0: *2 SSL buf copy: 7796
2014/08/12 09:15:10 [debug] 1370#0: *2 SSL to write: 16384
2014/08/12 09:15:10 [debug] 1370#0: *2 SSL_write: -1
2014/08/12 09:15:10 [debug] 1370#0: *2 SSL_get_error: 5
2014/08/12 09:15:10 [crit] 1370#0: *2 SSL_write() failed (SSL:) (1:
Operation not permitted) while processing SPDY, client: 10.0.0.2,
server:
0.0.0.0:443
2014/08/12 09:15:10 [debug] 1370#0: *2 http write filter
FFFFFFFFFFFFFFFF
2014/08/12 09:15:10 [debug] 1370#0: *2 http copy filter: -1
“/video/homepage.mp4?start=0”
2014/08/12 09:15:10 [debug] 1370#0: *2 http finalize request: -1,
“/video/homepage.mp4?start=0” a:1, c:1
2014/08/12 09:15:10 [debug] 1370#0: *2 http terminate request count:1
2014/08/12 09:15:10 [debug] 1370#0: *2 http terminate cleanup count:1
blk:0
2014/08/12 09:15:10 [debug] 1370#0: *2 http posted request:
“/video/homepage.mp4?start=0”
2014/08/12 09:15:10 [debug] 1370#0: *2 http terminate handler count:1
2014/08/12 09:15:10 [debug] 1370#0: *2 http request count:1 blk:0
2014/08/12 09:15:10 [debug] 1370#0: *2 spdy close stream 61, queued 3,
processing 1
2014/08/12 09:15:10 [debug] 1370#0: *2 spdy frame complete
pos:00000008021E8095 end:00000008021E80A1
2014/08/12 09:15:10 [debug] 1370#0: *2 process spdy frame head:80030006
f:0
l:4
2014/08/12 09:15:10 [debug] 1370#0: *2 spdy PING frame
2014/08/12 09:15:10 [debug] 1370#0: *2 spdy frame complete
pos:00000008021E80A1 end:00000008021E80A1
2014/08/12 09:15:10 [debug] 1370#0: *2 spdy close stream handler
2014/08/12 09:15:10 [debug] 1370#0: *2 spdy close stream 61, queued 0,
processing 1
2014/08/12 09:15:10 [debug] 1370#0: *2 http close request
2014/08/12 09:15:10 [debug] 1370#0: *2 http log handler
2014/08/12 09:15:10 [debug] 1370#0: *2 run cleanup: 00000008021AFDA0
2014/08/12 09:15:10 [debug] 1370#0: *2 file cleanup: fd:10
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 0000000802239000
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 0000000803006000
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 00000008021AB000
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 00000008021AF000, unused: 0
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 00000008021AA000, unused:
227
2014/08/12 09:15:10 [debug] 1370#0: *2 close http connection: 3
2014/08/12 09:15:10 [debug] 1370#0: *2 SSL_shutdown: 1
2014/08/12 09:15:10 [debug] 1370#0: *2 event timer del: 3: 1407835071420
2014/08/12 09:15:10 [debug] 1370#0: *2 reusable connection: 0
2014/08/12 09:15:10 [debug] 1370#0: *2 run cleanup: 0000000802101530
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 00000008021AE000, unused:
3040
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 00000008021A6000
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 0000000802231000
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 00000008021AD000
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 0000000802132000
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 0000000802106000
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 0000000802081000
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 0000000802104000
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 000000080208B000
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 00000008020E3380
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 0000000802101000, unused: 0
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 0000000802101200, unused: 0
2014/08/12 09:15:10 [debug] 1370#0: *2 free: 0000000802101500, unused:
32
2014/08/12 09:15:10 [debug] 1370#0: timer delta: 17793
2014/08/12 09:15:10 [debug] 1370#0: posted events 0000000000000000
2014/08/12 09:15:10 [debug] 1370#0: worker cycle
2014/08/12 09:15:10 [debug] 1370#0: kevent timer: -1, changes: 0

==

Here is the server:

ssl_certificate /usr/local/etc/nginx/ssl/test.com.crt;
ssl_certificate_key /usr/local/etc/nginx/ssl/test.com.key;

Resumption

ssl_session_cache shared:SSL:10m;

Timeout

ssl_session_timeout 10m;

ssl_protocols SSLv3 TLSv1 TLSv1.1 TLSv1.2;
ssl_ciphers
‘ECDHE-RSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-
GCM-SHA256:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA256:ECDHE-RSA-AES256-SHA:ECDHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA256:DHE-RSA-AES128-SHA256:DHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA:ECDHE-RSA-DES-CBC3-SHA:EDH-RSA-DES-CBC3-SHA:AES256-GCM-SHA384:AES128-GCM-SHA256:AES256-SHA256:AES128-SHA256:AES256-SHA:AES128-SHA:DES-CBC3-SHA:HIGH:!aNULL:!eNULL:!EXPORT:!CAMELLIA:!DES:!MD5:!PSK:!RC4’;

ssl_prefer_server_ciphers on;

server {
listen 443 ssl spdy;
server_name dev.test.com;
ssl on;
add_header Strict-Transport-Security “max-age=31536000;
includeSubDomains”;

    root   /usr/local/www/dev.test.com;
    index  index.html index.htm;

    #gzip off;

    #charset koi8-r;

    fastcgi_param HTTPS on;

    location / {
        try_files $uri $uri/ /index.php?$args;

        location ~ \.php$ { include php-fpm; }
    }

    location ~ .mp4$ {
        mp4;
        mp4_buffer_size 4M;
        mp4_max_buffer_size 10M;
    }

    location ~ .flv$ {
        flv;
    }

    location ~* (file_a|file_b|file_c)\.php$ {
        include php-fpm;
    }

    location /uploaddir {
        location ~ \.php$ {return 403;}
    }

    #access_log  logs/host.access.log  main;
    #Deny access to '.' files and directories
    location ~ /\. {
        access_log off;
        log_not_found off;
        deny all;
    }
}

Looking at the debug logs:

2014/08/12 09:15:10 [debug] 1370#0: *2 SSL_write: -1
2014/08/12 09:15:10 [debug] 1370#0: *2 SSL_get_error: 5

Could this be an nginx ↔ openssl interface error?

Any help or pointers would be much appreciated.

Thanks

Posted at Nginx Forum:

2

Sorry forgot to add the nginx version, running on FreeBSD 10.0-Rlease-p7

nginx version: nginx/1.7.4
TLS SNI support enabled
configure arguments: --prefix=/usr/local/etc/nginx --with-cc-opt=‘-I
/usr/local/include’ --with-ld-opt=‘-L /usr/local/lib’
–conf-path=/usr/local/etc/nginx/nginx.conf
–sbin-path=/usr/local/sbin/nginx --pid-path=/var/run/nginx.pid
–error-log-path=/var/log/nginx-error.log --user=www --group=www
–with-debug --with-ipv6
–http-client-body-temp-path=/var/tmp/nginx/client_body_temp
–http-fastcgi-temp-path=/var/tmp/nginx/fastcgi_temp
–http-proxy-temp-path=/var/tmp/nginx/proxy_temp
–http-scgi-temp-path=/var/tmp/nginx/scgi_temp
–http-uwsgi-temp-path=/var/tmp/nginx/uwsgi_temp
–http-log-path=/var/log/nginx-access.log --with-http_flv_module
–with-http_mp4_module --with-http_realip_module
–with-http_stub_status_module --with-pcre --with-http_spdy_module
–with-http_ssl_module

Posted at Nginx Forum:

3

Just an update, I forgot to add,

It seems it’s possibly related to chrome? (currently running Version
33.0.1750.117)

I converted the mp4 to ogv, same issue, but only in chrome, the android
version of chrome refuses to load period. Firefox is fine.

So probably not nginx related at all.

Posted at Nginx Forum: