Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Digest crashes with md5 #2

Closed
anordby opened this issue Dec 20, 2012 · 10 comments
Closed

Digest crashes with md5 #2

anordby opened this issue Dec 20, 2012 · 10 comments
Labels
backport-review-4.0

Comments

@anordby
Copy link

anordby commented Dec 20, 2012

When I use digest.hash_md5 with any value Varnish crashes:

(gdb) bt
#0 0x0000000801caa5d7 in strlen () from /lib/libc.so.7
#1 0x0000000000440f0f in VRT_StringList (

d=0x8083ce3e8 '0' <repeats 33 times>, "`??\t\bɵ(d\001Expect:", dl=63616, 
p=0x800 <Error reading address 0x800: Bad address>, ap=0x7fffedb5a390)
at cache_vrt.c:151

#2 0x00000000004410a9 in VRT_String (ws=0x8083cd080,

h=0x807502c56 "X-WURFL-Device:", p=0x8083ce3b0 '0' <repeats 32 times>, 
ap=0x7fffedb5a390) at cache_vrt.c:186

#3 0x0000000000441431 in VRT_SetHdr (sp=0x8083cd008, where=HDR_REQ,

hdr=0x807502c55 "\017X-WURFL-Device:", 
p=0x8083ce3b0 '0' <repeats 32 times>) at cache_vrt.c:230

#4 0x0000000807502338 in ?? ()
#5 0x00000008083cd398 in ?? ()
#6 0x000000000068272e in H_Expect ()
#7 0x0000000000000800 in ?? ()
#8 0x00007fffedb5a4d0 in ?? ()
#9 0x0000000802008400 in ?? ()
#10 0x000000000043faf7 in VCL_recv_method (sp=0x0) at vcl_returns.h:23

Previous frame inner to this frame (corrupt stack?)
(gdb) quit

My setup:

  • the latest digest vmod from github (I pulled it today)
  • varnish 3.0.3
  • FreeBSD/amd64 9.1-RC1
  • also using wurfl vmod by Scienta Mobile which I am testing
  • digest.sha1 works fine. No crash.
@KristianLyng
Copy link
Contributor

Could you try to run the test cases?

This is mighty strange, as the vmod-code is as close to algorithm agnostic as it gets.

@anordby
Copy link
Author

anordby commented Dec 21, 2012

Hi,

On tor, des 20, 2012 at 11:29:37am -0800, Kristian Lyngstøl wrote:

Could you try to run the test cases?

This is mighty strange, as the vmod-code is as close to algorithm agnostic as it gets.

Attached test case runs.

Bye

Anders.
**** top 0.0 macro def varnishd=/usr/ports/www/varnish/work/varnish-3.0.3/bin/varnishd/varnishd
**** top 0.0 macro def vmod_topbuild=/root/libvmod-digest
**** top 0.0 macro def pwd=/root/libvmod-digest/src
**** top 0.0 macro def topbuild=/root/libvmod-digest/src/../..
**** top 0.0 macro def bad_ip=10.255.255.255
**** top 0.0 macro def tmpdir=/tmp/vtc.50468.21858f2c

  • top 0.0 TEST tests/test01.vtc starting
    *** top 0.0 varnishtest
  • top 0.0 TEST Test digest vmod
    *** top 0.0 server
    ** s1 0.0 Starting server
    **** s1 0.0 macro def s1_addr=127.0.0.1
    **** s1 0.0 macro def s1_port=26876
    **** s1 0.0 macro def s1_sock=127.0.0.1 26876
  • s1 0.0 Listen on 127.0.0.1 26876
    ** s1 0.0 Started on 127.0.0.1 26876
    *** top 0.0 varnish
    ** v1 0.0 Launch
    *** v1 0.0 CMD: cd ${pwd} && ${varnishd} -d -d -n /tmp/vtc.50468.21858f2c/v1 -l 10m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -a '127.0.0.1:0' -S /tmp/vtc.50468.21858f2c/v1/_S -M '127.0.0.1 53717' -P /tmp/vtc.50468.21858f2c/v1/varnishd.pid -sfile,/tmp/vtc.50468.21858f2c/v1,10M
    *** v1 0.0 CMD: cd /root/libvmod-digest/src && /usr/ports/www/varnish/work/varnish-3.0.3/bin/varnishd/varnishd -d -d -n /tmp/vtc.50468.21858f2c/v1 -l 10m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -a '127.0.0.1:0' -S /tmp/vtc.50468.21858f2c/v1/_S -M '127.0.0.1 53717' -P /tmp/vtc.50468.21858f2c/v1/varnishd.pid -sfile,/tmp/vtc.50468.21858f2c/v1,10M
    *** v1 0.0 PID: 50485
    *** v1 0.0 debug| Platform: FreeBSD,9.1-RC1,amd64,-sfile,-smalloc,-hcritbit\n
    *** v1 0.0 debug| 200 234 \n
    *** v1 0.0 debug| -----------------------------\n
    *** v1 0.0 debug| Varnish Cache CLI 1.0\n
    *** v1 0.0 debug| -----------------------------\n
    *** v1 0.0 debug| FreeBSD,9.1-RC1,amd64,-sfile,-smalloc,-hcritbit\n
    *** v1 0.0 debug| \n
    *** v1 0.0 debug| Type 'help' for command list.\n
    *** v1 0.0 debug| Type 'quit' to close CLI session.\n
    *** v1 0.0 debug| Type 'start' to launch worker process.\n
    *** v1 0.0 debug| \n
    **** v1 0.1 CLIPOLL 1 0x1 0x0
    *** v1 0.1 CLI connection fd = 9
    *** v1 0.1 CLI RX 107
    **** v1 0.1 CLI RX| vijerbvqvriwsczjtbxpxwpoxsipppjn\n
    **** v1 0.1 CLI RX| \n
    **** v1 0.1 CLI RX| Authentication required.\n
    **** v1 0.1 CLI TX| auth 79c362c6be6b044ed8f101b5384031d7f569f9e94ba0e157c23b373f5c35dca2\n
    *** v1 0.1 CLI RX 200
    **** v1 0.1 CLI RX| -----------------------------\n
    **** v1 0.1 CLI RX| Varnish Cache CLI 1.0\n
    **** v1 0.1 CLI RX| -----------------------------\n
    **** v1 0.1 CLI RX| FreeBSD,9.1-RC1,amd64,-sfile,-smalloc,-hcritbit\n
    **** v1 0.1 CLI RX| \n
    **** v1 0.1 CLI RX| Type 'help' for command list.\n
    **** v1 0.1 CLI RX| Type 'quit' to close CLI session.\n
    **** v1 0.1 CLI RX| Type 'start' to launch worker process.\n
    **** v1 0.1 CLI TX| vcl.inline vcl1 << %XJEIFLH|)Xspa8P\n
    **** v1 0.1 CLI TX| backend s1 { .host = "127.0.0.1"; .port = "26876"; }\n
    **** v1 0.1 CLI TX| \n
    **** v1 0.1 CLI TX| \n
    **** v1 0.1 CLI TX| \timport digest from "/root/libvmod-digest/src/.libs/libvmod_digest.so";\n
    **** v1 0.1 CLI TX| \n
    **** v1 0.1 CLI TX| \tsub vcl_deliver {\n
    **** v1 0.1 CLI TX| \t\tset resp.http.sha256 = digest.hmac_sha256("key", "The quick brown fox jumps over the lazy dog");\n
    **** v1 0.1 CLI TX| \t\tset resp.http.sha1 = digest.hmac_sha1("key", "The quick brown fox jumps over the lazy dog");\n
    **** v1 0.1 CLI TX| \t\tset resp.http.md5 = digest.hmac_md5("key", "The quick brown fox jumps over the lazy dog");\n
    **** v1 0.1 CLI TX| \t\tset resp.http.sha256_b64 = digest.base64(...
    *** v1 0.4 CLI RX 200
    **** v1 0.4 CLI RX| VCL compiled.
    **** v1 0.4 CLI TX| vcl.use vcl1
    *** v1 0.5 CLI RX 200
    ** v1 0.5 Start
    **** v1 0.5 CLI TX| start
    *** v1 0.6 debug| child (50505) Started\n
    **** v1 0.6 vsl| 0 WorkThread - 0x7fffff3f9be0 start
    *** v1 0.6 debug| Child (50505) said Child starts\n
    *** v1 0.6 debug| Child (50505) said SMF.s0 mmap'ed 10485760 bytes of 10485760\n
    *** v1 0.6 CLI RX 200
    *** v1 0.6 wait-running
    **** v1 0.6 CLI TX| status
    **** v1 0.6 vsl| 0 CLI - Rd vcl.load "vcl1" ./vcl.GoW3u4Fe.so
    **** v1 0.6 vsl| 0 CLI - Wr 200 36 Loaded "./vcl.GoW3u4Fe.so" as "vcl1"
    **** v1 0.6 vsl| 0 CLI - Rd vcl.use "vcl1"
    **** v1 0.6 vsl| 0 CLI - Wr 200 0
    **** v1 0.6 vsl| 0 CLI - Rd start
    **** v1 0.6 vsl| 0 Debug - Acceptor is kqueue
    **** v1 0.6 vsl| 0 CLI - Wr 200 0
    **** v1 0.6 vsl| 0 WorkThread - 0x7ffffebf5be0 start
    **** v1 0.6 vsl| 0 WorkThread - 0x7ffffe9f4be0 start
    **** v1 0.6 vsl| 0 WorkThread - 0x7ffffe7f3be0 start
    **** v1 0.6 vsl| 0 WorkThread - 0x7ffffe5f2be0 start
    **** v1 0.6 vsl| 0 WorkThread - 0x7ffffe3f1be0 start
    **** v1 0.6 vsl| 0 WorkThread - 0x7ffffe1f0be0 start
    **** v1 0.6 vsl| 0 WorkThread - 0x7ffffdfefbe0 start
    **** v1 0.6 vsl| 0 WorkThread - 0x7ffffddeebe0 start
    **** v1 0.6 vsl| 0 WorkThread - 0x7ffffdbedbe0 start
    *** v1 0.7 CLI RX 200
    **** v1 0.7 CLI RX| Child in state running
    **** v1 0.7 CLI TX| debug.xid 1000
    *** v1 0.8 CLI RX 200
    **** v1 0.8 CLI RX| XID is 1000
    **** v1 0.8 CLI TX| debug.listen_address
    **** v1 0.8 vsl| 0 CLI - Rd debug.xid 1000
    **** v1 0.8 vsl| 0 CLI - Wr 200 11 XID is 1000
    *** v1 0.9 CLI RX 200
    **** v1 0.9 CLI RX| 127.0.0.1 16766\n
    ** v1 0.9 Listen on 127.0.0.1 16766
    **** v1 0.9 macro def v1_addr=127.0.0.1
    **** v1 0.9 macro def v1_port=16766
    **** v1 0.9 macro def v1_sock=127.0.0.1 16766
    *** top 0.9 client
    *** top 0.9 client
    ** c1 0.9 Starting client
    ** c1 0.9 Waiting for client
    *** c1 0.9 Connect to 127.0.0.1 16766
    *** c1 0.9 connected fd 10 from 127.0.0.1 50994 to 127.0.0.1 16766
    *** c1 0.9 txreq
    **** c1 0.9 txreq| GET / HTTP/1.1\r\n
    **** c1 0.9 txreq| \r\n
    *** c1 0.9 rxresp
    *** s1 0.9 accepted fd 4
    *** s1 0.9 rxreq
    **** s1 0.9 rxhdr| GET / HTTP/1.1\r\n
    **** s1 0.9 rxhdr| X-Forwarded-For: 127.0.0.1\r\n
    **** s1 0.9 rxhdr| X-Varnish: 1001\r\n
    **** s1 0.9 rxhdr| Accept-Encoding: gzip\r\n
    **** s1 0.9 rxhdr| Host: 127.0.0.1\r\n
    **** s1 0.9 rxhdr| \r\n
    **** s1 0.9 http[ 0] | GET
    **** s1 0.9 http[ 1] | /
    **** s1 0.9 http[ 2] | HTTP/1.1
    **** s1 0.9 http[ 3] | X-Forwarded-For: 127.0.0.1
    **** s1 0.9 http[ 4] | X-Varnish: 1001
    **** s1 0.9 http[ 5] | Accept-Encoding: gzip
    **** s1 0.9 http[ 6] | Host: 127.0.0.1
    **** s1 0.9 bodylen = 0
    *** s1 0.9 txresp
    **** s1 0.9 txresp| HTTP/1.1 200 Ok\r\n
    **** s1 0.9 txresp| Content-Length: 0\r\n
    **** s1 0.9 txresp| \r\n
    *** s1 0.9 shutting fd 4
    ** s1 0.9 Ending
    ---- c1 0.9 HTTP rx EOF (fd:10 read: No error: 0)
  • top 0.9 RESETTING after tests/test01.vtc
    ** s1 0.9 Waiting for server
    **** s1 0.9 macro undef s1_addr
    **** s1 0.9 macro undef s1_port
    **** s1 0.9 macro undef s1_sock
    *** v1 0.9 debug| Child (50505) died signal=6\n
    *** v1 0.9 debug| Child (50505) Panic message: Assert error in WS_Assert(), cache_ws.c line 50:\n
    *** v1 0.9 debug| Condition((ws) != NULL) not true.\n
    *** v1 0.9 debug| thread = (cache-worker)\n
    *** v1 0.9 debug| ident = FreeBSD,9.1-RC1,amd64,-sfile,-smalloc,-hcritbit,kqueue\n
    *** v1 0.9 debug| Backtrace:\n
    *** v1 0.9 debug| 0x4376df: pan_ic+19f\n
    *** v1 0.9 debug| 0x4499c1: WS_Assert+41\n
    *** v1 0.9 debug| 0x44a0b9: WS_Alloc+19\n
    *** v1 0.9 debug| 0x805206ac0: _end+804b808b0\n
    *** v1 0.9 debug| 0x805001532: _end+80497b322\n
    *** v1 0.9 debug| 0x417f6f: cnt_prepresp+52f\n
    *** v1 0.9 debug| 0x41cf72: CNT_Session+7b2\n
    *** v1 0.9 debug| 0x438c69: wrk_thread_real+889\n
    *** v1 0.9 debug| 0x43910a: wrk_thread+12a\n
    *** v1 0.9 debug| 0x8019930a4: _end+80130ce94\n
    *** v1 0.9 debug| sp = 0x805c61008 {\n
    *** v1 0.9 debug| fd = 7, id = 7, xid = 1001,\n
    *** v1 0.9 debug| client = 127.0.0.1 50994,\n
    *** v1 0.9 debug| step = STP_PREPRESP,\n
    *** v1 0.9 debug| handling = deliver,\n
    *** v1 0.9 debug| err_code = 200, err_reason = (null),\n
    *** v1 0.9 debug| restarts = 0, esi_level = 0\n
    *** v1 0.9 debug| flags = is_gunzip\n
    *** v1 0.9 debug| bodystatus = 4\n
    *** v1 0.9 debug| ws = 0x805c61080 { \n
    *** v1 0.9 debug| id = "sess",\n
    *** v1 0.9 debug| {s,f,r,e} = {0x805c61c68,+232,0x0,+65536},\n
    *** v1 0.9 debug| },\n
    *** v1 0.9 debug| http[req] = {\n
    *** v1 0.9 debug| ws = 0x805c61080[sess]\n
    *** v1 0.9 debug| "GET",\n
    *** v1 0.9 debug| "/",\n
    *** v1 0.9 debug| "HTTP/1.1",\n
    *** v1 0.9 debug| "X-Forwarded-For: 127.0.0.1",\n
    *** v1 0.9 debug| },\n
    *** v1 0.9 debug| worker = 0x7ffffdbedbe0 {\n
    *** v1 0.9 debug| ws = 0x7ffffdbeddf0 { \n
    *** v1 0.9 debug| id = "wrk",\n
    *** v1 0.9 debug| {s,f,r,e
    *** v1 0.9 debug| } = {0x7ffffdbdbaf0,+296,0x0,+65536},\n
    *** v1 0.9 debug| },\n
    *** v1 0.9 debug| http[resp] = {\n
    *** v1 0.9 debug| ws = 0x7ffffdbeddf0[wrk]\n
    *** v1 0.9 debug| "HTTP/1.1",\n
    *** v1 0.9 debug| "Ok",\n
    *** v1 0.9 debug| "Content-Length: 0",\n
    *** v1 0.9 debug| "Accept-Ranges: bytes",\n
    *** v1 0.9 debug| "Date: Fri, 21 Dec 2012 15:01:28 GMT",\n
    *** v1 0.9 debug| "X-Varnish: 1001",\n
    *** v1 0.9 debug| "Age: 0",\n
    *** v1 0.9 debug| "Via: 1.1 varnish",\n
    *** v1 0.9 debug| "Connection: keep-alive",\n
    *** v1 0.9 debug| "sha256: 0xf7bc83f430538424b13298e6aa6fb143ef4d59a14946175997479dbc2d1a3cd8",\n
    *** v1 0.9 debug| "sha1: 0xde7c9b85b8b78aa6bc8a7a36f70a90701c9db4d9",\n
    *** v1 0.9 debug| },\n
    *** v1 0.9 debug| },\n
    *** v1 0.9 debug| vcl = {\n
    *** v1 0.9 debug| srcname = {\n
    *** v1 0.9 debug| "input",\n
    *** v1 0.9 debug| "Default",\n
    *** v1 0.9 debug| },\n
    *** v1 0.9 debug| },\n
    *** v1 0.9 debug| obj = 0x803800000 {\n
    *** v1 0.9 debug| xid = 1001,\n
    *** v1 0.9 debug| ws = 0x803800018 { \n
    *** v1 0.9 debug| id = "obj",\n
    *** v1 0.9 debug| {s,f,r,e} = {0x803800188,+48,0x0,+80},\n
    *** v1 0.9 debug| },\n
    *** v1 0.9 debug| http[obj] = {\n
    *** v1 0.9 debug| ws = 0x803800018[obj]\n
    *** v1 0.9 debug| "HTTP/1.1",\n
    *** v1 0.9 debug| "Ok",\n
    *** v1 0.9 debug| "Content-Length: 0",\n
    *** v1 0.9 debug| },\n
    *** v1 0.9 debug| len = 0,\n
    *** v1 0.9 debug| store = {\n
    *** v1 0.9 debug| },\n
    *** v1 0.9 debug| },\n
    *** v1 0.9 debug| },\n
    *** v1 0.9 debug| \n
    *** v1 0.9 debug| \n
    *** v1 0.9 debug| Child cleanup complete\n
    **** v1 0.9 vsl| 0 CLI - Rd debug.listen_address
    **** v1 0.9 vsl| 0 CLI - Wr 200 16 127.0.0.1 16766

**** v1 0.9 vsl| 7 SessionOpen c 127.0.0.1 50994 127.0.0.1:0
**** v1 0.9 vsl| 7 ReqStart c 127.0.0.1 50994 1001
**** v1 0.9 vsl| 7 RxRequest c GET
**** v1 0.9 vsl| 7 RxURL c /
**** v1 0.9 vsl| 7 RxProtocol c HTTP/1.1
**** v1 0.9 vsl| 7 VCL_call c recv
**** v1 0.9 vsl| 7 VCL_return c lookup
**** v1 0.9 vsl| 7 VCL_call c hash
**** v1 0.9 vsl| 7 Hash c /
**** v1 0.9 vsl| 7 Hash c 127.0.0.1
**** v1 0.9 vsl| 7 VCL_return c hash
**** v1 0.9 vsl| 7 VCL_call c miss
**** v1 0.9 vsl| 7 VCL_return c fetch
**** v1 0.9 vsl| 10 BackendOpen b s1 127.0.0.1 54099 127.0.0.1 26876
**** v1 0.9 vsl| 7 Backend c 10 s1 s1
**** v1 0.9 vsl| 10 TxRequest b GET
**** v1 0.9 vsl| 10 TxURL b /
**** v1 0.9 vsl| 10 TxProtocol b HTTP/1.1
**** v1 0.9 vsl| 10 TxHeader b X-Forwarded-For: 127.0.0.1
**** v1 0.9 vsl| 10 TxHeader b X-Varnish: 1001
**** v1 0.9 vsl| 10 TxHeader b Accept-Encoding: gzip
**** v1 0.9 vsl| 10 TxHeader b Host: 127.0.0.1
**** v1 0.9 vsl| 10 RxProtocol b HTTP/1.1
**** v1 0.9 vsl| 10 RxStatus b 200
**** v1 0.9 vsl| 10 RxResponse b Ok
**** v1 0.9 vsl| 10 RxHeader b Content-Length: 0
**** v1 0.9 vsl| 7 TTL c 1001 RFC 120 -1 -1 1356102089 0 0 0 0
**** v1 0.9 vsl| 7 VCL_call c fetch
**** v1 0.9 vsl| 7 VCL_return c deliver
**** v1 0.9 vsl| 7 ObjProtocol c HTTP/1.1
**** v1 0.9 vsl| 7 ObjResponse c Ok
**** v1 0.9 vsl| 10 Fetch_Body b 4(length) cls 0 mklen 1
**** v1 0.9 vsl| 10 Length b 0
**** v1 0.9 vsl| 10 BackendReuse b s1
** v1 1.9 Wait
** v1 1.9 R 50485 Status: 0000

  • top 1.9 TEST tests/test01.vtc FAILED

top TEST tests/test01.vtc FAILED (1.936) exit=1

**** top 0.0 macro def varnishd=/usr/ports/www/varnish/work/varnish-3.0.3/bin/varnishd/varnishd
**** top 0.0 macro def vmod_topbuild=/root/libvmod-digest
**** top 0.0 macro def pwd=/root/libvmod-digest/src
**** top 0.0 macro def topbuild=/root/libvmod-digest/src/../..
**** top 0.0 macro def bad_ip=10.255.255.255
**** top 0.0 macro def tmpdir=/tmp/vtc.50507.17867ab1

  • top 0.0 TEST tests/test_hash.vtc starting
    *** top 0.0 varnishtest
  • top 0.0 TEST Test various hashes
    *** top 0.0 server
    ** s1 0.0 Starting server
    **** s1 0.0 macro def s1_addr=127.0.0.1
    **** s1 0.0 macro def s1_port=10866
    **** s1 0.0 macro def s1_sock=127.0.0.1 10866
  • s1 0.0 Listen on 127.0.0.1 10866
    ** s1 0.0 Started on 127.0.0.1 10866
    *** top 0.0 varnish
    ** v1 0.0 Launch
    *** v1 0.0 CMD: cd ${pwd} && ${varnishd} -d -d -n /tmp/vtc.50507.17867ab1/v1 -l 10m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -a '127.0.0.1:0' -S /tmp/vtc.50507.17867ab1/v1/_S -M '127.0.0.1 18921' -P /tmp/vtc.50507.17867ab1/v1/varnishd.pid -sfile,/tmp/vtc.50507.17867ab1/v1,10M
    *** v1 0.0 CMD: cd /root/libvmod-digest/src && /usr/ports/www/varnish/work/varnish-3.0.3/bin/varnishd/varnishd -d -d -n /tmp/vtc.50507.17867ab1/v1 -l 10m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -a '127.0.0.1:0' -S /tmp/vtc.50507.17867ab1/v1/_S -M '127.0.0.1 18921' -P /tmp/vtc.50507.17867ab1/v1/varnishd.pid -sfile,/tmp/vtc.50507.17867ab1/v1,10M
    *** v1 0.0 PID: 50524
    *** v1 0.0 debug| Platform: FreeBSD,9.1-RC1,amd64,-sfile,-smalloc,-hcritbit\n
    *** v1 0.0 debug| 200 234 \n
    *** v1 0.0 debug| -----------------------------\n
    *** v1 0.0 debug| Varnish Cache CLI 1.0\n
    *** v1 0.0 debug| -----------------------------\n
    *** v1 0.0 debug| FreeBSD,9.1-RC1,amd64,-sfile,-smalloc,-hcritbit\n
    *** v1 0.0 debug| \n
    *** v1 0.0 debug| Type 'help' for command list.\n
    *** v1 0.0 debug| Type 'quit' to close CLI session.\n
    *** v1 0.0 debug| Type 'start' to launch worker process.\n
    *** v1 0.0 debug| \n
    **** v1 0.1 CLIPOLL 1 0x1 0x0
    *** v1 0.1 CLI connection fd = 9
    *** v1 0.1 CLI RX 107
    **** v1 0.1 CLI RX| bdgqrgjljaoktzmlcenicleggrqxhcpi\n
    **** v1 0.1 CLI RX| \n
    **** v1 0.1 CLI RX| Authentication required.\n
    **** v1 0.1 CLI TX| auth 098f47166ae05a71d3de21249958e82a4c8b07ccf204789725056e26b2e6f6ff\n
    *** v1 0.1 CLI RX 200
    **** v1 0.1 CLI RX| -----------------------------\n
    **** v1 0.1 CLI RX| Varnish Cache CLI 1.0\n
    **** v1 0.1 CLI RX| -----------------------------\n
    **** v1 0.1 CLI RX| FreeBSD,9.1-RC1,amd64,-sfile,-smalloc,-hcritbit\n
    **** v1 0.1 CLI RX| \n
    **** v1 0.1 CLI RX| Type 'help' for command list.\n
    **** v1 0.1 CLI RX| Type 'quit' to close CLI session.\n
    **** v1 0.1 CLI RX| Type 'start' to launch worker process.\n
    **** v1 0.1 CLI TX| vcl.inline vcl1 << %XJEIFLH|)Xspa8P\n
    **** v1 0.1 CLI TX| backend s1 { .host = "127.0.0.1"; .port = "10866"; }\n
    **** v1 0.1 CLI TX| \n
    **** v1 0.1 CLI TX| \n
    **** v1 0.1 CLI TX| \timport digest from "/root/libvmod-digest/src/.libs/libvmod_digest.so";\n
    **** v1 0.1 CLI TX| \n
    **** v1 0.1 CLI TX| \tsub vcl_deliver {\n
    **** v1 0.1 CLI TX| \t\tif (req.url == "/1") {\t\t\n
    **** v1 0.1 CLI TX| \t\t\tset resp.http.CRC32_1 = digest.hash_crc32("checksum");\n
    **** v1 0.1 CLI TX| \t\t\tset resp.http.CRC32B_2 = digest.hash_crc32b("checksum");\n
    **** v1 0.1 CLI TX| \t\t\tset resp.http.GOST_66 = digest.hash_gost("This is message, length=32 bytes");\n
    **** v1 0.1 CLI TX| \t\t\tset resp.http.GOST_67 = digest.hash_gost("Suppose the original message has length = 50 bytes");\n
    **** v1 0.1 CLI TX| \t\t\tse...
    *** v1 0.5 CLI RX 200
    **** v1 0.5 CLI RX| VCL compiled.
    **** v1 0.5 CLI TX| vcl.use vcl1
    *** v1 0.6 CLI RX 200
    ** v1 0.6 Start
    **** v1 0.6 CLI TX| start
    *** v1 0.7 debug| child (50544) Started\n
    **** v1 0.7 vsl| 0 WorkThread - 0x7fffff3f9be0 start
    *** v1 0.7 debug| Child (50544) said Child starts\n
    *** v1 0.7 debug| Child (50544) said SMF.s0 mmap'ed 10485760 bytes of 10485760\n
    *** v1 0.7 CLI RX 200
    *** v1 0.7 wait-running
    **** v1 0.7 CLI TX| status
    **** v1 0.7 vsl| 0 CLI - Rd vcl.load "vcl1" ./vcl.pUQtqzfD.so
    **** v1 0.7 vsl| 0 CLI - Wr 200 36 Loaded "./vcl.pUQtqzfD.so" as "vcl1"
    **** v1 0.7 vsl| 0 CLI - Rd vcl.use "vcl1"
    **** v1 0.7 vsl| 0 CLI - Wr 200 0
    **** v1 0.7 vsl| 0 CLI - Rd start
    **** v1 0.7 vsl| 0 Debug - Acceptor is kqueue
    **** v1 0.7 vsl| 0 CLI - Wr 200 0
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffebf5be0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffe9f4be0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffe7f3be0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffe5f2be0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffe3f1be0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffe1f0be0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffdfefbe0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffddeebe0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffdbedbe0 start
    *** v1 0.8 CLI RX 200
    **** v1 0.8 CLI RX| Child in state running
    **** v1 0.8 CLI TX| debug.xid 1000
    *** v1 0.9 CLI RX 200
    **** v1 0.9 CLI RX| XID is 1000
    **** v1 0.9 CLI TX| debug.listen_address
    **** v1 1.0 vsl| 0 CLI - Rd debug.xid 1000
    **** v1 1.0 vsl| 0 CLI - Wr 200 11 XID is 1000
    *** v1 1.0 CLI RX 200
    **** v1 1.0 CLI RX| 127.0.0.1 31466\n
    ** v1 1.0 Listen on 127.0.0.1 31466
    **** v1 1.0 macro def v1_addr=127.0.0.1
    **** v1 1.0 macro def v1_port=31466
    **** v1 1.0 macro def v1_sock=127.0.0.1 31466
    *** top 1.0 client
    *** top 1.0 client
    ** c1 1.0 Starting client
    ** c1 1.0 Waiting for client
    *** c1 1.0 Connect to 127.0.0.1 31466
    *** c1 1.0 connected fd 10 from 127.0.0.1 59311 to 127.0.0.1 31466
    *** c1 1.0 txreq
    **** c1 1.0 txreq| GET /1 HTTP/1.1\r\n
    **** c1 1.0 txreq| \r\n
    *** c1 1.0 rxresp
    *** s1 1.0 accepted fd 4
    *** s1 1.0 rxreq
    **** s1 1.0 rxhdr| GET /1 HTTP/1.1\r\n
    **** s1 1.0 rxhdr| X-Forwarded-For: 127.0.0.1\r\n
    **** s1 1.0 rxhdr| X-Varnish: 1001\r\n
    **** s1 1.0 rxhdr| Accept-Encoding: gzip\r\n
    **** s1 1.0 rxhdr| Host: 127.0.0.1\r\n
    **** s1 1.0 rxhdr| \r\n
    **** s1 1.0 http[ 0] | GET
    **** s1 1.0 http[ 1] | /1
    **** s1 1.0 http[ 2] | HTTP/1.1
    **** s1 1.0 http[ 3] | X-Forwarded-For: 127.0.0.1
    **** s1 1.0 http[ 4] | X-Varnish: 1001
    **** s1 1.0 http[ 5] | Accept-Encoding: gzip
    **** s1 1.0 http[ 6] | Host: 127.0.0.1
    **** s1 1.0 bodylen = 0
    *** s1 1.0 txresp
    **** s1 1.0 txresp| HTTP/1.1 200 Ok\r\n
    **** s1 1.0 txresp| Content-Length: 0\r\n
    **** s1 1.0 txresp| \r\n
    *** s1 1.0 rxreq
    ---- s1 1.0 HTTP rx EOF (fd:4 read: No error: 0)
    ---- c1 1.0 HTTP rx EOF (fd:10 read: No error: 0)
  • top 1.0 RESETTING after tests/test_hash.vtc
    ** s1 1.0 Waiting for server
    **** s1 1.0 macro undef s1_addr
    **** s1 1.0 macro undef s1_port
    **** s1 1.0 macro undef s1_sock
    *** v1 1.0 debug| Child (50544) died signal=11\n
    *** v1 1.0 debug| Child cleanup complete\n
    **** v1 1.0 vsl| 0 CLI - Rd debug.listen_address
    **** v1 1.0 vsl| 0 CLI - Wr 200 16 127.0.0.1 31466

**** v1 1.0 vsl| 7 SessionOpen c 127.0.0.1 59311 127.0.0.1:0
**** v1 1.0 vsl| 7 ReqStart c 127.0.0.1 59311 1001
**** v1 1.0 vsl| 7 RxRequest c GET
**** v1 1.0 vsl| 7 RxURL c /1
**** v1 1.0 vsl| 7 RxProtocol c HTTP/1.1
**** v1 1.0 vsl| 7 VCL_call c recv
**** v1 1.0 vsl| 7 VCL_return c lookup
**** v1 1.0 vsl| 7 VCL_call c hash
**** v1 1.0 vsl| 7 Hash c /1
**** v1 1.0 vsl| 7 Hash c 127.0.0.1
**** v1 1.0 vsl| 7 VCL_return c hash
**** v1 1.0 vsl| 7 VCL_call c miss
**** v1 1.0 vsl| 7 VCL_return c fetch
**** v1 1.0 vsl| 10 BackendOpen b s1 127.0.0.1 52356 127.0.0.1 10866
**** v1 1.0 vsl| 7 Backend c 10 s1 s1
**** v1 1.0 vsl| 10 TxRequest b GET
**** v1 1.0 vsl| 10 TxURL b /1
**** v1 1.0 vsl| 10 TxProtocol b HTTP/1.1
**** v1 1.0 vsl| 10 TxHeader b X-Forwarded-For: 127.0.0.1
**** v1 1.0 vsl| 10 TxHeader b X-Varnish: 1001
**** v1 1.0 vsl| 10 TxHeader b Accept-Encoding: gzip
**** v1 1.0 vsl| 10 TxHeader b Host: 127.0.0.1
**** v1 1.0 vsl| 10 RxProtocol b HTTP/1.1
**** v1 1.0 vsl| 10 RxStatus b 200
**** v1 1.0 vsl| 10 RxResponse b Ok
**** v1 1.0 vsl| 10 RxHeader b Content-Length: 0
**** v1 1.0 vsl| 7 TTL c 1001 RFC 120 -1 -1 1356102109 0 0 0 0
**** v1 1.0 vsl| 7 VCL_call c fetch
**** v1 1.0 vsl| 7 VCL_return c deliver
**** v1 1.0 vsl| 7 ObjProtocol c HTTP/1.1
**** v1 1.0 vsl| 7 ObjResponse c Ok
**** v1 1.0 vsl| 10 Fetch_Body b 4(length) cls 0 mklen 1
**** v1 1.0 vsl| 10 Length b 0
**** v1 1.0 vsl| 10 BackendReuse b s1
** v1 2.0 Wait
** v1 2.0 R 50524 Status: 0000

  • top 2.1 TEST tests/test_hash.vtc FAILED

top TEST tests/test_hash.vtc FAILED (2.062) exit=1

top TEST tests/test_nullstring.vtc passed (1.111)

@KristianLyng
Copy link
Contributor

Hmm, this looks like something I'll have to look into in early January. Thanks for the test output, it suggests some nefarious stuff... Hopefully it'll be easy to spot.

@lkarsten
Copy link
Contributor

lkarsten commented Oct 7, 2013

Hi.

This has been laying stale after Kristian left the company. Sorry about that.

Had a look at this now, and on my debian wheezy system I'm not able to reproduce it.
The vmod test cases covers the md5 function, so make check should fail on systems where this bug manifests.

libmhash version is:
{{{
lkarsten@immer:/work/libvmod-digest$ dpkg -l | grep mhash
ii libmhash-dev 0.9.9.9-1.1 amd64 Library for cryptographic hashing and message authentication
ii libmhash2 0.9.9.9-1.1 amd64 Library for cryptographic hashing and message authentication
lkarsten@immer:/work/libvmod-digest$ dpkg -L libmhash2 | grep .so
/usr/lib/libmhash.so.2.0.1
/usr/lib/libmhash.so.2
lkarsten@immer:~/work/libvmod-digest$
}}}

I set up a travis-ci job for it as well, and it looks to pass nicely as well: https://travis-ci.org/lkarsten/libvmod-digest

My best guess here is that either is some other vmod/inline-C doing things it shouldn't, or libmhash on freebsd is different.

I ran 40kreq/s against digest.hash_md5() (in vcl_recv, setting req.http, not resp.http..) for 10 minutes now, and I haven't seen any crashes.

Are you still able to reproduce this?

@lkarsten
Copy link
Contributor

Nothing heard, closing this for now.

@anordby
Copy link
Author

anordby commented Feb 10, 2014

Sorry for the late response. But this has now become a serious issue for us. While doing some digest.hash_md5, Varnish constantly crashes:

Feb 10 11:34:10 cachetest1 kernel: pid 76808 (varnishd), uid 65534: exited on signal 11
Feb 10 10:34:10 cachetest1 varnishd[1296]: child (13501) Started
Feb 10 10:34:10 cachetest1 varnishd[1296]: Child (13501) said Child starts

If I

(gdb) bt
#0 0x0000000801c8c5d7 in strlen () from /lib/libc.so.7
#1 0x0000000000437ded in VRT_StringList ()
#2 0x0000000000437ee8 in VRT_String ()
#3 0x00000000004382b5 in VRT_WrkString ()
#4 0x000000080d80ac53 in ?? ()
#5 0x0000000000000000 in ?? ()
#6 0x000000080233e740 in ?? ()
#7 0x0000000807cf8008 in ?? ()
#8 0x0000000000000000 in ?? ()
#9 0x00007fffb0181bc0 in ?? ()
#10 0x00007fffb0181dd0 in ?? ()
#11 0x0000000802062ab0 in ?? ()
#12 0x000000080d80d72d in ?? ()
#13 0x0000000807cf8008 in ?? ()
#14 0x0000000000000000 in ?? ()
#15 0x0000000807cf8008 in ?? ()
#16 0x0000000000000000 in ?? ()
#17 0x00007fffb0181bc0 in ?? ()
#18 0x0000000000436e18 in VCL_recv_method ()
#19 0x000000000041916f in CNT_Session ()
#20 0x00000000004313d4 in wrk_thread_real ()
#21 0x00000008019750a4 in pthread_getprio () from /lib/libthr.so.3
#22 0x0000000000000000 in ?? ()
Error accessing memory address 0x7fffb0182000: Bad address.
(gdb)

Running the test cases, they fail:

[root@cachetest1 ~/libvmod-digest]# gmake check
Making check in src
gmake[1]: Entering directory `/root/libvmod-digest/src'
/usr/ports/www/varnish/work/varnish-3.0.3/bin/varnishtest/varnishtest -Dvarnishd=/usr/ports/www/varnish/work/varnish-3.0.3/bin/varnishd/varnishd -Dvmod_topbuild=/root/libvmod-digest tests/test01.vtc
**** top 0.0 macro def varnishd=/usr/ports/www/varnish/work/varnish-3.0.3/bin/varnishd/varnishd
**** top 0.0 macro def vmod_topbuild=/root/libvmod-digest
**** top 0.0 macro def pwd=/root/libvmod-digest/src
**** top 0.0 macro def topbuild=/root/libvmod-digest/src/../..
**** top 0.0 macro def bad_ip=10.255.255.255
**** top 0.0 macro def tmpdir=/tmp/vtc.21433.0320deb3

  • top 0.0 TEST tests/test01.vtc starting
    *** top 0.0 varnishtest
  • top 0.0 TEST Test digest vmod
    *** top 0.0 server
    ** s1 0.0 Starting server
    **** s1 0.0 macro def s1_addr=127.0.0.1
    **** s1 0.0 macro def s1_port=25270
    **** s1 0.0 macro def s1_sock=127.0.0.1 25270
  • s1 0.0 Listen on 127.0.0.1 25270
    *** top 0.0 varnish
    ** s1 0.0 Started on 127.0.0.1 25270
    ** v1 0.0 Launch
    *** v1 0.0 CMD: cd ${pwd} && ${varnishd} -d -d -n /tmp/vtc.21433.0320deb3/v1 -l 10m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -a '127.0.0.1:0' -S /tmp/vtc.21433.0320deb3/v1/_S -M '127.0.0.1 25271' -P /tmp/vtc.21433.0320deb3/v1/varnishd.pid -sfile,/tmp/vtc.21433.0320deb3/v1,10M
    *** v1 0.0 CMD: cd /root/libvmod-digest/src && /usr/ports/www/varnish/work/varnish-3.0.3/bin/varnishd/varnishd -d -d -n /tmp/vtc.21433.0320deb3/v1 -l 10m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -a '127.0.0.1:0' -S /tmp/vtc.21433.0320deb3/v1/_S -M '127.0.0.1 25271' -P /tmp/vtc.21433.0320deb3/v1/varnishd.pid -sfile,/tmp/vtc.21433.0320deb3/v1,10M
    *** v1 0.0 PID: 21450
    *** v1 0.1 debug| Platform: FreeBSD,9.1-RC1,amd64,-sfile,-smalloc,-hcritbit\n
    *** v1 0.1 debug| 200 234 \n
    *** v1 0.1 debug| -----------------------------\n
    *** v1 0.1 debug| Varnish Cache CLI 1.0\n
    *** v1 0.1 debug| -----------------------------\n
    *** v1 0.1 debug| FreeBSD,9.1-RC1,amd64,-sfile,-smalloc,-hcritbit\n
    *** v1 0.1 debug| \n
    *** v1 0.1 debug| Type 'help' for command list.\n
    *** v1 0.1 debug| Type 'quit' to close CLI session.\n
    *** v1 0.1 debug| Type 'start' to launch worker process.\n
    *** v1 0.1 debug| \n
    **** v1 0.2 CLIPOLL 1 0x1 0x0
    *** v1 0.2 CLI connection fd = 9
    *** v1 0.2 CLI RX 107
    **** v1 0.2 CLI RX| ymrebfwfoyseblrwqjdkpmmgohgcpzyo\n
    **** v1 0.2 CLI RX| \n
    **** v1 0.2 CLI RX| Authentication required.\n
    **** v1 0.2 CLI TX| auth eb6e37edd88fcc04f63bdce010cc02610b7e0cf403b6393d6885a87c885d39ac\n
    *** v1 0.2 CLI RX 200
    **** v1 0.2 CLI RX| -----------------------------\n
    **** v1 0.2 CLI RX| Varnish Cache CLI 1.0\n
    **** v1 0.2 CLI RX| -----------------------------\n
    **** v1 0.2 CLI RX| FreeBSD,9.1-RC1,amd64,-sfile,-smalloc,-hcritbit\n
    **** v1 0.2 CLI RX| \n
    **** v1 0.2 CLI RX| Type 'help' for command list.\n
    **** v1 0.2 CLI RX| Type 'quit' to close CLI session.\n
    **** v1 0.2 CLI RX| Type 'start' to launch worker process.\n
    **** v1 0.2 CLI TX| vcl.inline vcl1 << %XJEIFLH|)Xspa8P\n
    **** v1 0.2 CLI TX| backend s1 { .host = "127.0.0.1"; .port = "25270"; }\n
    **** v1 0.2 CLI TX| \n
    **** v1 0.2 CLI TX| \n
    **** v1 0.2 CLI TX| \timport digest from "/root/libvmod-digest/src/.libs/libvmod_digest.so";\n
    **** v1 0.2 CLI TX| \n
    **** v1 0.2 CLI TX| \tsub vcl_deliver {\n
    **** v1 0.2 CLI TX| \t\tset resp.http.sha256 = digest.hmac_sha256("key", "The quick brown fox jumps over the lazy dog");\n
    **** v1 0.2 CLI TX| \t\tset resp.http.sha1 = digest.hmac_sha1("key", "The quick brown fox jumps over the lazy dog");\n
    **** v1 0.2 CLI TX| \t\tset resp.http.md5 = digest.hmac_md5("key", "The quick brown fox jumps over the lazy dog");\n
    **** v1 0.2 CLI TX| \t\tset resp.http.sha256_b64 = digest.base64(...
    *** v1 0.5 CLI RX 200
    **** v1 0.5 CLI RX| VCL compiled.
    **** v1 0.5 CLI TX| vcl.use vcl1
    *** v1 0.6 CLI RX 200
    ** v1 0.6 Start
    **** v1 0.6 CLI TX| start
    *** v1 0.7 debug| child (21470) Started\n
    **** v1 0.7 vsl| 0 CLI - Rd vcl.load "vcl1" ./vcl.yA276UY3.so
    **** v1 0.7 vsl| 0 WorkThread - 0x7fffff3f9bc0 start
    **** v1 0.7 vsl| 0 CLI - Wr 200 36 Loaded "./vcl.yA276UY3.so" as "vcl1"
    **** v1 0.7 vsl| 0 CLI - Rd vcl.use "vcl1"
    **** v1 0.7 vsl| 0 CLI - Wr 200 0
    **** v1 0.7 vsl| 0 CLI - Rd start
    **** v1 0.7 vsl| 0 Debug - Acceptor is kqueue
    **** v1 0.7 vsl| 0 CLI - Wr 200 0
    *** v1 0.7 CLI RX 200
    *** v1 0.7 wait-running
    **** v1 0.7 CLI TX| status
    *** v1 0.7 debug| Child (21470) said Child starts\n
    *** v1 0.7 debug| Child (21470) said SMF.s0 mmap'ed 10485760 bytes of 10485760\n
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffebf5bc0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffe9f4bc0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffe7f3bc0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffe5f2bc0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffe3f1bc0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffe1f0bc0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffdfefbc0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffddeebc0 start
    **** v1 0.7 vsl| 0 WorkThread - 0x7ffffdbedbc0 start
    *** v1 0.8 CLI RX 200
    **** v1 0.8 CLI RX| Child in state running
    **** v1 0.8 CLI TX| debug.xid 1000
    *** v1 0.9 CLI RX 200
    **** v1 0.9 CLI RX| XID is 1000
    **** v1 0.9 CLI TX| debug.listen_address
    **** v1 0.9 vsl| 0 CLI - Rd debug.xid 1000
    **** v1 0.9 vsl| 0 CLI - Wr 200 11 XID is 1000
    *** v1 1.0 CLI RX 200
    **** v1 1.0 CLI RX| 127.0.0.1 25273\n
    ** v1 1.0 Listen on 127.0.0.1 25273
    **** v1 1.0 macro def v1_addr=127.0.0.1
    **** v1 1.0 macro def v1_port=25273
    **** v1 1.0 macro def v1_sock=127.0.0.1 25273
    *** top 1.0 client
    *** top 1.0 client
    ** c1 1.0 Starting client
    ** c1 1.0 Waiting for client
    *** c1 1.0 Connect to 127.0.0.1 25273
    *** c1 1.0 connected fd 10 from 127.0.0.1 25274 to 127.0.0.1 25273
    *** c1 1.0 txreq
    **** c1 1.0 txreq| GET / HTTP/1.1\r\n
    **** c1 1.0 txreq| \r\n
    *** c1 1.0 rxresp
    *** s1 1.0 accepted fd 4
    *** s1 1.0 rxreq
    **** s1 1.0 rxhdr| GET / HTTP/1.1\r\n
    **** s1 1.0 rxhdr| X-Forwarded-For: 127.0.0.1\r\n
    **** s1 1.0 rxhdr| X-Varnish: 1001\r\n
    **** s1 1.0 rxhdr| Accept-Encoding: gzip\r\n
    **** s1 1.0 rxhdr| Host: 127.0.0.1\r\n
    **** s1 1.0 rxhdr| \r\n
    **** s1 1.0 http[ 0] | GET
    **** s1 1.0 http[ 1] | /
    **** s1 1.0 http[ 2] | HTTP/1.1
    **** s1 1.0 http[ 3] | X-Forwarded-For: 127.0.0.1
    **** s1 1.0 http[ 4] | X-Varnish: 1001
    **** s1 1.0 http[ 5] | Accept-Encoding: gzip
    **** s1 1.0 http[ 6] | Host: 127.0.0.1
    **** s1 1.0 bodylen = 0
    *** s1 1.0 txresp
    **** s1 1.0 txresp| HTTP/1.1 200 Ok\r\n
    **** s1 1.0 txresp| Content-Length: 0\r\n
    **** s1 1.0 txresp| \r\n
    *** s1 1.0 shutting fd 4
    ** s1 1.0 Ending
    ---- c1 1.0 HTTP rx EOF (fd:10 read: No error: 0)
  • top 1.0 RESETTING after tests/test01.vtc
    ** s1 1.0 Waiting for server
    **** s1 1.0 macro undef s1_addr
    **** s1 1.0 macro undef s1_port
    **** s1 1.0 macro undef s1_sock
    *** v1 1.0 debug| Child (21470) died signal=11\n
    *** v1 1.0 debug| Child (21470) Panic message: Assert error in WS_Assert(), cache_ws.c line 50:\n
    *** v1 1.0 debug| Condition((ws) != NULL) not true.\n
    *** v1 1.0 debug| thread = (cache-worker)\n
    *** v1 1.0 debug| ident = FreeBSD,9.1-RC1,amd64,-sfile,-smalloc,-hcritbit,kqueue\n
    *** v1 1.0 debug| \n
    *** v1 1.0 debug| Child cleanup complete\n
    **** v1 1.0 vsl| 0 CLI - Rd debug.listen_address
    **** v1 1.0 vsl| 0 CLI - Wr 200 16 127.0.0.1 25273

**** v1 1.0 vsl| 7 SessionOpen c 127.0.0.1 25274 127.0.0.1:0
**** v1 1.0 vsl| 7 ReqStart c 127.0.0.1 25274 1001
**** v1 1.0 vsl| 7 RxRequest c GET
**** v1 1.0 vsl| 7 RxURL c /
**** v1 1.0 vsl| 7 RxProtocol c HTTP/1.1
**** v1 1.0 vsl| 7 VCL_call c recv
**** v1 1.0 vsl| 7 VCL_return c lookup
**** v1 1.0 vsl| 7 VCL_call c hash
**** v1 1.0 vsl| 7 Hash c /
**** v1 1.0 vsl| 7 Hash c 127.0.0.1
**** v1 1.0 vsl| 7 VCL_return c hash
**** v1 1.0 vsl| 7 VCL_call c miss
**** v1 1.0 vsl| 7 VCL_return c fetch
**** v1 1.0 vsl| 10 BackendOpen b s1 127.0.0.1 25275 127.0.0.1 25270
**** v1 1.0 vsl| 7 Backend c 10 s1 s1
**** v1 1.0 vsl| 10 TxRequest b GET
**** v1 1.0 vsl| 10 TxURL b /
**** v1 1.0 vsl| 10 TxProtocol b HTTP/1.1
**** v1 1.0 vsl| 10 TxHeader b X-Forwarded-For: 127.0.0.1
**** v1 1.0 vsl| 10 TxHeader b X-Varnish: 1001
**** v1 1.0 vsl| 10 TxHeader b Accept-Encoding: gzip
**** v1 1.0 vsl| 10 TxHeader b Host: 127.0.0.1
**** v1 1.0 vsl| 10 RxProtocol b HTTP/1.1
**** v1 1.0 vsl| 10 RxStatus b 200
**** v1 1.0 vsl| 10 RxResponse b Ok
**** v1 1.0 vsl| 10 RxHeader b Content-Length: 0
**** v1 1.0 vsl| 7 TTL c 1001 RFC 120 -1 -1 1392029013 0 0 0 0
**** v1 1.0 vsl| 7 VCL_call c fetch
**** v1 1.0 vsl| 7 VCL_return c deliver
**** v1 1.0 vsl| 7 ObjProtocol c HTTP/1.1
**** v1 1.0 vsl| 7 ObjResponse c Ok
**** v1 1.0 vsl| 10 Fetch_Body b 4(length) cls 0 mklen 1
**** v1 1.0 vsl| 10 Length b 0
**** v1 1.0 vsl| 10 BackendReuse b s1
** v1 2.0 Wait
** v1 2.0 R 21450 Status: 0000

  • top 2.0 TEST tests/test01.vtc FAILED

top TEST tests/test01.vtc FAILED (2.010) exit=1

gmake[1]: *** [tests/test01.vtc] Error 2
gmake[1]: Leaving directory `/root/libvmod-digest/src'
gmake: *** [check-recursive] Error 1

@lkarsten lkarsten reopened this Feb 10, 2014
@daghf
Copy link
Member

daghf commented Feb 11, 2014

Turns out there is a naming conflict between functions in libmd (which Varnish on freebsd/ports links against for some reason) and functions in libmhash. Upon loading vmod-digest various functions (MD5Init, MD5Final, MD5Update, ...) get resolved from /lib/libmd.so and not libmhash, with disastrous results. :-/

A workaround to make it prefer libmhash is to set LD_PRELOAD prior to launching varnishd.

The following command makes all the tests pass for me:

$ gmake check LD_PRELOAD=/usr/local/lib/libmhash.so

@daghf daghf closed this as completed Feb 11, 2014
@daghf daghf mentioned this issue Feb 11, 2014
Closed
tota pushed a commit to tota/freebsd-ports that referenced this issue Feb 20, 2014
Retire this digest patch. We don't want to use -lmd as it creates
c83e30a 
problems when using libmhash and/or digest vmod.

More info: varnish/libvmod-digest#2
tota pushed a commit to tota/freebsd-ports that referenced this issue Feb 21, 2014
Retire this digest patch. We don't want to use -lmd as it creates
28a5b3f 
problems when using libmhash and/or digest vmod.

More info: varnish/libvmod-digest#2


git-svn-id: svn+ssh://svn.freebsd.org/ports/head@345093 35697150-7ecd-e111-bb59-0022644237b5
@netw3rker
Copy link

I think this might still be an issue? am using a macports install of varnish-3.0.4, and a build of this off of the 3.0 branch. In addition, I had to build from source the mhash-0.9.9.9 library.

running "gmake check LD_PRELOAD=/usr/local/lib/libmhash.so" gives me the following test results:

root# gmake check LD_PRELOAD=/usr/local/lib/libmhash.so
Making check in src
gmake[1]: Entering directory '/opt/local/etc/varnish/source/libvmod-digest-3.0/src'
/opt/local/etc/varnish/source/varnish-3.0.4/bin/varnishtest/varnishtest -Dvarnishd=/opt/local/etc/varnish/source/varnish-3.0.4/bin/varnishd/varnishd -Dvmod_topbuild=/opt/local/etc/varnish/source/libvmod-digest-3.0 tests/test01.vtc
**** top   0.0 macro def varnishd=/opt/local/etc/varnish/source/varnish-3.0.4/bin/varnishd/varnishd
**** top   0.0 macro def vmod_topbuild=/opt/local/etc/varnish/source/libvmod-digest-3.0
**** top   0.0 macro def pwd=/opt/local/etc/varnish/source/libvmod-digest-3.0/src
**** top   0.0 macro def topbuild=/opt/local/etc/varnish/source/libvmod-digest-3.0/src/../..
**** top   0.0 macro def bad_ip=192.0.2.255
**** top   0.0 macro def tmpdir=/tmp/vtc.56939.666452bd
*    top   0.0 TEST tests/test01.vtc starting
***  top   0.0 varnishtest
*    top   0.0 TEST Test digest vmod
***  top   0.0 server
**   s1    0.0 Starting server
**** s1    0.0 macro def s1_addr=127.0.0.1
**** s1    0.0 macro def s1_port=53197
**** s1    0.0 macro def s1_sock=127.0.0.1 53197
*    s1    0.0 Listen on 127.0.0.1 53197
**   s1    0.0 Started on 127.0.0.1 53197
***  top   0.0 varnish
**   v1    0.0 Launch
***  v1    0.0 CMD: cd ${pwd} && ${varnishd} -d -d -n /tmp/vtc.56939.666452bd/v1 -l 10m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -a '127.0.0.1:0' -S /tmp/vtc.56939.666452bd/v1/_S -M '127.0.0.1 53198' -P /tmp/vtc.56939.666452bd/v1/varnishd.pid -sfile,/tmp/vtc.56939.666452bd/v1,10M 
***  v1    0.0 CMD: cd /opt/local/etc/varnish/source/libvmod-digest-3.0/src && /opt/local/etc/varnish/source/varnish-3.0.4/bin/varnishd/varnishd -d -d -n /tmp/vtc.56939.666452bd/v1 -l 10m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -a '127.0.0.1:0' -S /tmp/vtc.56939.666452bd/v1/_S -M '127.0.0.1 53198' -P /tmp/vtc.56939.666452bd/v1/varnishd.pid -sfile,/tmp/vtc.56939.666452bd/v1,10M 
***  v1    0.0 PID: 56957
***  v1    0.1 debug| Platform: Darwin,14.1.0,x86_64,-sfile,-smalloc,-hcritbit\n
***  v1    0.1 debug| 200 264     \n
***  v1    0.1 debug| -----------------------------\n
***  v1    0.1 debug| Varnish Cache CLI 1.0\n
***  v1    0.1 debug| -----------------------------\n
***  v1    0.1 debug| Darwin,14.1.0,x86_64,-sfile,-smalloc,-hcritbit\n
***  v1    0.1 debug| varnish-3.0.4 revision 9f83e8f\n
***  v1    0.1 debug| \n
***  v1    0.1 debug| Type 'help' for command list.\n
***  v1    0.1 debug| Type 'quit' to close CLI session.\n
***  v1    0.1 debug| Type 'start' to launch worker process.\n
***  v1    0.1 debug| \n
**** v1    0.2 CLIPOLL 1 0x1 0x0
***  v1    0.2 CLI connection fd = 8
***  v1    0.2 CLI RX  107
**** v1    0.2 CLI RX| txyeehlozzmkuiszmsjiuvcxjjosplai\n
**** v1    0.2 CLI RX| \n
**** v1    0.2 CLI RX| Authentication required.\n
**** v1    0.2 CLI TX| auth 55b16955d46c5ee57a071e9a89b3c025c2c4f65598e671f40646314ce5ad82db\n
***  v1    0.2 CLI RX  200
**** v1    0.2 CLI RX| -----------------------------\n
**** v1    0.2 CLI RX| Varnish Cache CLI 1.0\n
**** v1    0.2 CLI RX| -----------------------------\n
**** v1    0.2 CLI RX| Darwin,14.1.0,x86_64,-sfile,-smalloc,-hcritbit\n
**** v1    0.2 CLI RX| varnish-3.0.4 revision 9f83e8f\n
**** v1    0.2 CLI RX| \n
**** v1    0.2 CLI RX| Type 'help' for command list.\n
**** v1    0.2 CLI RX| Type 'quit' to close CLI session.\n
**** v1    0.2 CLI RX| Type 'start' to launch worker process.\n
**** v1    0.2 CLI TX| vcl.inline vcl1 << %XJEIFLH|)Xspa8P\n
**** v1    0.2 CLI TX| backend s1 { .host = "127.0.0.1"; .port = "53197"; }\n
**** v1    0.2 CLI TX| \n
**** v1    0.2 CLI TX| \n
**** v1    0.2 CLI TX| \timport digest from "/opt/local/etc/varnish/source/libvmod-digest-3.0/src/.libs/libvmod_digest.so";\n
**** v1    0.2 CLI TX| \n
**** v1    0.2 CLI TX| \tsub vcl_deliver {\n
**** v1    0.2 CLI TX| \t\tset resp.http.sha256 = digest.hmac_sha256("key", "The quick brown fox jumps over the lazy dog");\n
**** v1    0.2 CLI TX| \t\tset resp.http.sha1 = digest.hmac_sha1("key", "The quick brown fox jumps over the lazy dog");\n
**** v1    0.2 CLI TX| \t\tset resp.http.md5 = digest.hmac_md5("key", "The quick brown fox jumps over the lazy dog");\n
**** v1    0.2 CLI TX| \t\tset resp.http...
***  v1    0.3 CLI RX  200
**** v1    0.3 CLI RX| VCL compiled.
**** v1    0.3 CLI TX| vcl.use vcl1
***  v1    0.3 CLI RX  200
**   v1    0.3 Start
**** v1    0.3 CLI TX| start
***  v1    0.3 debug| child (56979) Started\n
**** v1    0.3 vsl|     0 WorkThread   - 0x10fa14b00 start
**** v1    0.3 vsl|     0 CLI          - Rd vcl.load "vcl1" ./vcl.It4ikVeR.so
***  v1    0.3 CLI RX  200
***  v1    0.3 wait-running
**** v1    0.3 CLI TX| status
***  v1    0.3 debug| Child (56979) said Child starts\n
***  v1    0.3 debug| Child (56979) said SMF.s0 mmap'ed 10485760 bytes of 10485760\n
***  v1    0.3 CLI RX  200
**** v1    0.3 CLI RX| Child in state running
**** v1    0.3 CLI TX| debug.xid 1000
***  v1    0.3 CLI RX  200
**** v1    0.3 CLI RX| XID is 1000
**** v1    0.3 CLI TX| debug.listen_address
***  v1    0.3 CLI RX  200
**** v1    0.3 CLI RX| 127.0.0.1 53200\n
**   v1    0.3 Listen on 127.0.0.1 53200
**** v1    0.3 macro def v1_addr=127.0.0.1
**** v1    0.3 macro def v1_port=53200
**** v1    0.3 macro def v1_sock=127.0.0.1 53200
***  top   0.3 client
***  top   0.3 client
**   c1    0.3 Starting client
**   c1    0.3 Waiting for client
***  c1    0.3 Connect to 127.0.0.1 53200
***  c1    0.3 connected fd 9 from 127.0.0.1 53201 to 127.0.0.1 53200
**** v1    0.3 vsl|     0 CLI          - Wr 200 36 Loaded "./vcl.It4ikVeR.so" as "vcl1"
**** v1    0.3 vsl|     0 CLI          - Rd vcl.use "vcl1"
**** v1    0.3 vsl|     0 CLI          - Wr 200 0 
**** v1    0.3 vsl|     0 CLI          - Rd start
***  c1    0.3 txreq
**** v1    0.3 vsl|     0 Debug        - Acceptor is kqueue
**** v1    0.3 vsl|     0 CLI          - Wr 200 0 
**** v1    0.3 vsl|     0 CLI          - Rd debug.xid 1000 
**** v1    0.3 vsl|     0 CLI          - Wr 200 11 XID is 1000
**** v1    0.3 vsl|     0 CLI          - Rd debug.listen_address 
**** v1    0.3 vsl|     0 CLI          - Wr 200 16 127.0.0.1 53200

**** c1    0.3 txreq| GET / HTTP/1.1\r\n
**** c1    0.3 txreq| \r\n
***  c1    0.3 rxresp
**** v1    0.3 vsl|     0 WorkThread   - 0x1107e2b00 start
**** v1    0.3 vsl|     0 WorkThread   - 0x110865b00 start
**** v1    0.3 vsl|     0 WorkThread   - 0x1108e8b00 start
**** v1    0.3 vsl|     0 WorkThread   - 0x11096bb00 start
***  s1    0.3 accepted fd 10
***  s1    0.3 rxreq
**** s1    0.3 rxhdr| GET / HTTP/1.1\r\n
**** s1    0.3 rxhdr| X-Forwarded-For: 127.0.0.1\r\n
**** s1    0.3 rxhdr| X-Varnish: 1001\r\n
**** s1    0.3 rxhdr| Accept-Encoding: gzip\r\n
**** s1    0.3 rxhdr| Host: 127.0.0.1\r\n
**** s1    0.3 rxhdr| \r\n
**** s1    0.3 http[ 0] | GET
**** s1    0.3 http[ 1] | /
**** s1    0.3 http[ 2] | HTTP/1.1
**** s1    0.3 http[ 3] | X-Forwarded-For: 127.0.0.1
**** s1    0.3 http[ 4] | X-Varnish: 1001
**** s1    0.3 http[ 5] | Accept-Encoding: gzip
**** s1    0.3 http[ 6] | Host: 127.0.0.1
**** s1    0.3 bodylen = 0
***  s1    0.3 txresp
**** s1    0.3 txresp| HTTP/1.1 200 Ok\r\n
**** s1    0.3 txresp| Content-Length: 0\r\n
**** s1    0.3 txresp| \r\n
***  s1    0.3 shutting fd 10
**   s1    0.3 Ending
**** v1    0.3 vsl|     0 WorkThread   - 0x1109eeb00 start
**** v1    0.3 vsl|     7 SessionOpen  c 127.0.0.1 53201 127.0.0.1:0
**** v1    0.3 vsl|     7 ReqStart     c 127.0.0.1 53201 1001
**** v1    0.3 vsl|     7 RxRequest    c GET
**** v1    0.3 vsl|     7 RxURL        c /
**** v1    0.3 vsl|     7 RxProtocol   c HTTP/1.1
**** v1    0.3 vsl|     7 VCL_call     c recv
**** v1    0.3 vsl|     7 VCL_return   c lookup
**** v1    0.3 vsl|     7 VCL_call     c hash
**** v1    0.3 vsl|     7 Hash         c /
**** v1    0.3 vsl|     7 Hash         c 127.0.0.1
**** v1    0.3 vsl|     7 VCL_return   c hash
**** v1    0.3 vsl|     7 VCL_call     c miss
**** v1    0.3 vsl|     7 VCL_return   c fetch
**** v1    0.3 vsl|    10 BackendOpen  b s1 127.0.0.1 53202 127.0.0.1 53197
**** v1    0.3 vsl|     7 Backend      c 10 s1 s1
**** v1    0.3 vsl|    10 TxRequest    b GET
**** v1    0.3 vsl|    10 TxURL        b /
**** v1    0.3 vsl|    10 TxProtocol   b HTTP/1.1
**** v1    0.3 vsl|    10 TxHeader     b X-Forwarded-For: 127.0.0.1
**** v1    0.3 vsl|    10 TxHeader     b X-Varnish: 1001
**** v1    0.3 vsl|    10 TxHeader     b Accept-Encoding: gzip
**** v1    0.3 vsl|    10 TxHeader     b Host: 127.0.0.1
**** v1    0.3 vsl|    10 RxProtocol   b HTTP/1.1
**** v1    0.3 vsl|    10 RxStatus     b 200
**** v1    0.3 vsl|    10 RxResponse   b Ok
**** v1    0.3 vsl|    10 RxHeader     b Content-Length: 0
**** v1    0.3 vsl|     7 TTL          c 1001 RFC 120 -1 -1 1429499934 0 0 0 0
**** v1    0.3 vsl|     7 VCL_call     c fetch
**** v1    0.3 vsl|     7 VCL_return   c deliver
**** v1    0.3 vsl|     7 ObjProtocol  c HTTP/1.1
**** v1    0.3 vsl|     7 ObjResponse  c Ok
**** v1    0.3 vsl|    10 Fetch_Body   b 4(length) cls 0 mklen 1
**** v1    0.3 vsl|    10 Length       b 0
**** v1    0.3 vsl|    10 BackendReuse b s1
---- c1    0.6 HTTP rx EOF (fd:9 read: Undefined error: 0)
***  v1    0.6 debug| Child (56979) died signal=11\n
*    top   0.6 RESETTING after tests/test01.vtc
**   s1    0.6 Waiting for server
**** s1    0.6 macro undef s1_addr
**** s1    0.6 macro undef s1_port
**** s1    0.6 macro undef s1_sock
***  v1    0.6 debug| Child cleanup complete\n
**   v1    1.6 Wait
**   v1    1.6 R 56957 Status: 0000
*    top   1.6 TEST tests/test01.vtc FAILED

#     top  TEST tests/test01.vtc FAILED (1.569) exit=1
Makefile:659: recipe for target 'tests/test01.vtc' failed
gmake[1]: *** [tests/test01.vtc] Error 2
gmake[1]: Leaving directory '/opt/local/etc/varnish/source/libvmod-digest-3.0/src'
Makefile:495: recipe for target 'check-recursive' failed
gmake: *** [check-recursive] Error 1

any thoughts on how to get varnish to stop dying with md5 is called?

@aondio
Copy link
Contributor

aondio commented Apr 20, 2015

I'll reopen this issue.
I've checked the behavior on linux and debian and I haven't been able to reproduce such an error.
This should be just freebsd related.

@aondio aondio reopened this Apr 20, 2015
@daghf
Copy link
Member

daghf commented Jan 21, 2016

Please try a more recent version, if you can still reproduce it feel free to reopen.

@daghf daghf closed this as completed Jan 21, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
backport-review-4.0
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
7 participants
@lkarsten @KristianLyng @anordby @netw3rker @daghf @aondio @vssync