[Varnish] #1399: Memory get freed while in use by another thread/object

[Varnish]

#1399: Memory get freed while in use by another thread/object
-------------------------------------------------+-------------------------
 Reporter:  varnish@…                            |       Type:  defect
   Status:  new                                  |   Priority:  normal
Milestone:  Varnish 4.0-TP1                      |  Component:  varnishd
  Version:  trunk                                |   Severity:  major
 Keywords:  memory get freed MPL_Free            |
  vbf_stp_fetchhdr                               |
-------------------------------------------------+-------------------------
 Hi,

 prerequisites:
  - compiled varnishd via "./configure --enable-debugging-symbols
 --without-jemalloc"
  - start varnishd from commandline
 {{{
 varnishd -n VARNISH -f default.vcl -n /var/tmp/ -a :8080 -p
 default_grace=10 -p default_ttl=5 -p ping_interval=0 -p auto_restart=off
 -d
 }}}
  - start the child process via start
  - configure a single backend w/o health probes
  - start two consecutive requests to varnish with a pause of
 $backend_keepalive_timeout + 1 second
  - backend is a apache httpd with 10s keepalive timeout

 while debugging issue #1398 I've found another issue, which was a little
 bit more complicated to debug.

 While a backend request is made, the busyobject bereq structures get
 filled by the following functions:
  - vbf_stp_mkbereq -> bo->bereq0 get populted from bo->req->http
  - vbf_stp_startfetch -> bo->bereq get copied from bo->bereq0

 After this was done, the headers will be fetched from backend via
 vbf_stp_fetchhdr.

 After the first request was made, a new object will saved by varnish. If
 you now wait for the keep alive timeout of your backend and then starting
 the second request, the object will be gracefully delivered by varnish to
 the client, but the ongoing backend request will fail, because another
 thread has freed the initial (?) req object from memory.

 The result is, that the backend responses with an error or in a
 virtualhost environment the first vhost which matches the backend ip. You
 can see the bereq structur in ticket #1398, the URL and some headers get
 deleted from the bereq structure.

 For me it looks like the problem leys in vbf_stp_startfetch(), where the
 bo->bereq structure will be copied from the bo->bereq0 object. Either the
 header should be duplicated, since the protocol and method get also
 duplicated (but this could be for conditional fetches) or the req object
 inside the busyobject structure should be protected from improper
 invalidation (disclaimer: this opinion could be totally wrong).

 I've found this bug with the help of gdb, following my commands which I've
 executed:
 {{{
 (gdb) b vbf_stp_fetchhdr
 Breakpoint 1 at 0x422304: file cache/cache_fetch.c, line 148.
 (gdb) c
 Continuing.
 [Switching to Thread 0x7f853931b700 (LWP 11382)]

 Breakpoint 1, vbf_stp_fetchhdr (wrk=0x7f853931ac20, bo=0x7f851c090a90) at
 cache/cache_fetch.c:148
 148             CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
 (gdb) c
 Continuing.

 Breakpoint 1, vbf_stp_fetchhdr (wrk=0x7f853931ac20, bo=0x7f851c090a90) at
 cache/cache_fetch.c:148
 148             CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
 (gdb) p bo->bereq->hd[1]
 $3 = {b = 0x7f8510092a6d "/", e = 0x7f8510092a6e ""}
 (gdb) p bo->bereq->hd[1].b
 $4 = 0x7f8510092a6d "/"
 (gdb) watch *0x7f8510092a6d
 Hardware watchpoint 2: *0x7f8510092a6d
 (gdb) c
 Continuing.
 [Switching to Thread 0x7f85392f7700 (LWP 11385)]
 Hardware watchpoint 2: *0x7f8510092a6d

 Old value = 1414004783
 New value = 1409286144
 __memset_sse2 () at ../sysdeps/x86_64/memset.S:880
 880             movdqa %xmm0,0x60(%rdi)
 (gdb) bt
 #0  __memset_sse2 () at ../sysdeps/x86_64/memset.S:880
 #1  0x0000000000435eec in MPL_Free (mpl=0x7f8534000a20,
 item=0x7f8510090a90) at cache/cache_mempool.c:322
 #2  0x0000000000441ed2 in SES_ReleaseReq (req=0x7f8510090a90) at
 cache/cache_session.c:437
 #3  0x000000000042ff5f in http1_wait (sp=0x7f8514001540,
 wrk=0x7f85392f6c20, req=0x7f8510090a90) at cache/cache_http1_fsm.c:159
 #4  0x0000000000431106 in HTTP1_Session (wrk=0x7f85392f6c20,
 req=0x7f8510090a90) at cache/cache_http1_fsm.c:437
 #5  0x000000000044062e in ses_req_pool_task (wrk=0x7f85392f6c20,
 arg=0x7f8510090a90) at cache/cache_session.c:148
 #6  0x0000000000440856 in ses_sess_pool_task (wrk=0x7f85392f6c20,
 arg=0x7f8514001540) at cache/cache_session.c:173
 #7  0x0000000000440d69 in SES_pool_accept_task (wrk=0x7f85392f6c20,
 arg=0x7f85340009f0) at cache/cache_session.c:243
 #8  0x0000000000439607 in Pool_Work_Thread (priv=0x7f85340008c0,
 wrk=0x7f85392f6c20) at cache/cache_pool.c:295
 #9  0x00000000004520e4 in wrk_thread_real (priv=0x7f85340008c0,
 thread_workspace=2048) at cache/cache_wrk.c:143
 #10 0x000000000045220d in WRK_thread (priv=0x7f85340008c0) at
 cache/cache_wrk.c:161
 #11 0x00007f854d8349d1 in start_thread (arg=0x7f85392f7700) at
 pthread_create.c:301
 #12 0x00007f854d581b6d in clone () at
 ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
 (gdb) q
 }}}

 1. attach to the child
 2. set a breakpoint to vbf_stp_fetchhdr()
 3. start the first request in another terminal
 4. continue this execution of vbf_stp_fetchhdr() - it's the first request
 which works
 5. start the second request in another terminal
 6. print the memory address of the header we want to watch
 7. set the wwatchpoint for the memory address which holds our important
 value
 8. continue execution
 9. watchpoint will be trapped by another thread which deallocates the req
 structures

 Please let me know if you need more information.

 Best regards,
 Martin

-- 
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1399>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator