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

insilica nginx-forum at nginx.us
Tue Aug 12 09:28:36 UTC 2014


Hi,

I've searched the mailing list but haven't found anything relating to this
error:, the closest I found: http://trac.nginx.org/nginx/ticket/428 -
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: http://forum.nginx.org/read.php?2,252494,252494#msg-252494



More information about the nginx mailing list