weird error log 'live: already publishing' when doing rtmp 302

[spacewander]

When I try to do rtmp 302, I always see a weird error log live: already publishing in the error.log file, though the rtmp 302 works well. When stopping Nginx, sometimes I also notice a memory leak detected by ASAN:

Direct leak of 48 byte(s) in 1 object(s) allocated from:
    #0 0x4fdf10 in __interceptor_malloc (/usr/local/openresty/nginx/sbin/nginx+0x4fdf10)
    #1 0x62b2d8 in ngx_alloc .../openresty-1.15.8.2/build/nginx-1.15.8/src/os/unix/ngx_alloc.c:22:9
    #2 0x544574 in ngx_create_pool .../openresty-1.15.8.2/build/nginx-1.15.8/src/core/ngx_palloc.c:22:9
    #3 0xda6e1d in ngx_rtmp_gop_cache_publish .../nginx-http-flv-module/ngx_rtmp_gop_cache_module.c:801:21
    #4 0xdb5548 in ngx_rtmp_live_publish .../nginx-http-flv-module/ngx_rtmp_live_module.c:1578:12
    #5 0xe04ecf in ngx_rtmp_relay_publish .../nginx-http-flv-module/ngx_rtmp_relay_module.c:1120:12
    #6 0xe17e6c in ngx_rtmp_exec_publish .../nginx-http-flv-module/ngx_rtmp_exec_module.c:1190:12
    #7 0xdf76cb in ngx_rtmp_auto_pull_publish .../nginx-http-flv-module/ngx_rtmp_auto_pull_module.c:952:12
    #8 0xe28d79 in ngx_rtmp_notify_publish .../nginx-http-flv-module/ngx_rtmp_notify_module.c:1500:12
    #9 0xe396af in ngx_rtmp_log_publish .../nginx-http-flv-module/ngx_rtmp_log_module.c:1360:12
    #10 0xe6130c in ngx_rtmp_hls_publish .../nginx-http-flv-module/hls/ngx_rtmp_hls_module.c:1474:12
    #11 0xe7420d in ngx_rtmp_dash_publish .../nginx-http-flv-module/dash/ngx_rtmp_dash_module.c:948:12
    #12 0xe23fc5 in ngx_rtmp_auto_push_publish .../nginx-http-flv-module/ngx_rtmp_auto_push_module.c:519:12
    #13 0xe0b15f in ngx_rtmp_relay_publish_local .../nginx-http-flv-module/ngx_rtmp_relay_module.c:1208:12
    #14 0xe05d9a in ngx_rtmp_relay_on_result .../nginx-http-flv-module/ngx_rtmp_relay_module.c:1696:24
    #15 0xd7d715 in ngx_rtmp_amf_message_handler .../nginx-http-flv-module/ngx_rtmp_receive.c:437:21
    #16 0xd6439c in ngx_rtmp_receive_message .../nginx-http-flv-module/ngx_rtmp_handler.c:939:17
    #17 0xd5b768 in ngx_rtmp_recv .../nginx-http-flv-module/ngx_rtmp_handler.c:530:17
    #18 0x6546c8 in ngx_epoll_process_events .../openresty-1.15.8.2/build/nginx-1.15.8/src/event/modules/ngx_epoll_module.c:902:17
    #19 0x6092f3 in ngx_process_events_and_timers .../openresty-1.15.8.2/build/nginx-1.15.8/src/event/ngx_event.c:252:12
    #20 0x649915 in ngx_worker_process_cycle .../openresty-1.15.8.2/build/nginx-1.15.8/src/os/unix/ngx_process_cycle.c:816:9
    #21 0x63d646 in ngx_spawn_process .../openresty-1.15.8.2/build/nginx-1.15.8/src/os/unix/ngx_process.c:199:9
    #22 0x644363 in ngx_start_worker_processes .../openresty-1.15.8.2/build/nginx-1.15.8/src/os/unix/ngx_process_cycle.c:397:9
    #23 0x642896 in ngx_master_process_cycle .../openresty-1.15.8.2/build/nginx-1.15.8/src/os/unix/ngx_process_cycle.c:136:5
    #24 0x5375df in main .../openresty-1.15.8.2/build/nginx-1.15.8/src/core/nginx.c:382:9
    #25 0x7fb186fbab96 in __libc_start_main /build/glibc-OTsEL5/glibc-2.27/csu/../csu/libc-start.c:310

The pool is expected to be released in:

nginx-http-flv-module/ngx_rtmp_gop_cache_module.c

Line 935 in aee1608

if (gctx->pool) {

My Nginx configuration is:

daemon off;
worker_processes  1;

error_log stderr  info;

events {
    worker_connections  4096;
}

http {
    server {
        listen 8888;
        location / {
            content_by_lua_block {
                ngx.redirect("rtmp://127.0.0.1:1935/app/1")
            }
        }
    }
}

rtmp {
    server {
        listen 19350 default_server reuseport;

        on_play http://127.0.0.1:8888/on_play;
        notify_method get;

        application app {
            live on;
            gop_cache on;
        }
    }

    server {
        listen 1935;
        application app {
            live on;
            gop_cache on;
            deny publish all;
            pull rtmp://127.0.0.1:19350/app/1;
        }
    }
}

The http://127.0.0.1:8888/on_play will return status code 302 and redirect the client to port 1935, then server listening port 1935 will pull the rtmp stream from port 19350.

The stream is created by ffmpeg -re -i ~/data/dump.mp4 -c copy -f flv rtmp://127.0.0.1:19350/app/1 -loglevel info, and the client is vlc 'rtmp://127.0.0.1:19350/app/1'.

After applying patch below, the memory leak can't be detected anymore:

diff --git a/ngx_rtmp_live_module.c b/ngx_rtmp_live_module.c
index aa9e70f..7b215d6 100644
--- a/ngx_rtmp_live_module.c
+++ b/ngx_rtmp_live_module.c
@@ -651,12 +651,17 @@ ngx_rtmp_live_join(ngx_rtmp_session_t *s, u_char *name, unsigned publisher)

     if (publisher) {
         if ((*stream)->publishing) {
-            ngx_log_error(NGX_LOG_ERR, s->connection->log, 0,
-                          "live: already publishing");
-
             ngx_rtmp_send_status(s, "NetStream.Publish.BadName", "error",
                                  "Already publishing");

+            if (!ctx->publishing) {
+                ctx->publishing = 1;
+                return;
+            }
+
+            ngx_log_error(NGX_LOG_ERR, s->connection->log, 0,
+                          "live: already publishing");
+
             return;
         }

I am not sure if the problem is fixed totally.

[winshining]

Great!
There is indeed a memory leak in that situation, thank you for posting the issue. But I think the patch is incorrect because it is not actually publishing. The modified code may potentially lead to some problems.
I will fix it later, thank you!

[spacewander]

Thank you for your quick response!

[winshining]

Hello, the bug was fixed.
The memory pool is created in publish function in gop module without checking if stream is publishing in live module. If stream is not publishing (ctx->publishing == 0), the created pool will not be destroyed, memory leak occurs.
By the way, "live: already publishing" is not weird, it will always happen if configuration file as yours is used.
Thanks again for posting the issue!