Assert error in Lck_CondWait(), cache/cache_lck.c line 203 (on Mac OS X) #1853

bsdphk · 2016-03-04T13:31:49Z

Old ticket imported from Trac
See archived copy here: https://varnish-cache.org/trac/ticket/1853

nigoroll · 2016-06-16T10:43:35Z

@mjastrzebowski are you the original reporter of the (archived) ticket?

nigoroll · 2016-06-16T11:08:05Z

The way I read the MacOS manpage, this should not be happening, also the panic trace provided shows that errno==0 (because there is no errno = line present in the panic), so I'd say this smells like a macos bug.
Would you please try to reproduce on master (or at least a more current varnish version) and reopen if the issue still exists?

lkarsten · 2016-06-27T14:58:41Z

Backport review: nothing commited.

lkarsten · 2016-06-28T15:11:51Z

Got access to a osx instance now, and had to satisfy my curiosity.

On OSX pthread_cond_wait() can return non-null, the man page documents that EINVAL is a valid return code. There is no mention of errno being used, I think @nigoroll misread the man page on that point.

Discussed this a bit with Martin. Since this happens in VBT_Wait() this could be an issue with our kqueue waiter and/or tcp pools implementation.

It would require some effort to follow up on this, and since the original reporter has gone quiet and OSX is a nice-to-have platform, I think Nils did the right thing by closing it for now.

yousefcisco · 2018-05-01T21:10:01Z

I'm consistently getting this error on a number of OSX machines. Is there any way I can help debug / get to the root of the issue?

Debug: Platform: Darwin,17.5.0,x86_64,-jnone,-smalloc,-sdefault,-hcritbit
Debug: Child (92772) Started
Info: Child (92772) said Child starts
Error: Child (92772) died signal=6
Error: Child (92772) Panic at: Tue, 01 May 2018 21:02:30 GMT
Assert error in Lck_CondWait(), cache/cache_lck.c line 210:
  Condition(errno == 0 || errno == ETIMEDOUT || errno == EINTR) not true.
version = varnish-6.0.0 revision a068361dff0d25a0d85cf82a6e5fdaf315e06a7d, vrt api = 7.0
ident = Darwin,17.5.0,x86_64,-jnone,-smalloc,-sdefault,-hcritbit,kqueue
now = 1256819.952568 (mono), 1525208550.563772 (real)
Backtrace:
  0x10b829f77: 0   varnishd                            0x000000010b829f77 pan_ic + 429
  0x10b889040: 0   varnishd                            0x000000010b889040 VAS_Fail + 116
  0x10b82626b: 0   varnishd                            0x000000010b82626b Lck_CondWait + 349
  0x10b836b74: 0   varnishd                            0x000000010b836b74 VTP_Wait + 166
  0x10b80ab46: 0   varnishd                            0x000000010b80ab46 vbe_dir_gethdrs + 458
  0x10b812310: 0   varnishd                            0x000000010b812310 VDI_GetHdr + 102
  0x10b81a04b: 0   varnishd                            0x000000010b81a04b vbf_fetch_thread + 2337
  0x10b847721: 0   varnishd                            0x000000010b847721 WRK_Thread + 1181
  0x10b847231: 0   varnishd                            0x000000010b847231 pool_thread + 56
  0x7fff710d7661: 0   libsystem_pthread.dylib             0x00007fff710d7661 _pthread_body + 340
errno = 22 (Invalid argument)
thread = (cache-worker)
thr.req = 0x0 {
},
thr.busyobj = 0x7f870087a020 {
  ws = 0x7f870087a058 {
    id = \"bo\",
    {s, f, r, e} = {0x7f870087bf50, +1824, 0x0, +57512},
  },
  retries = 0, failed = 0, flags = {do_stream, do_pass, uncacheable},
  http_conn = 0x7f870087c610 {
    fd = 33 (@0x7f86fef18b04),
    doclose = NULL,
    ws = 0x0 {
    },
    {rxbuf_b, rxbuf_e} = {0x0, 0x0},
    {pipeline_b, pipeline_e} = {0x0, 0x0},
    content_length = 0,
    body_status = none,
    first_byte_timeout = 60.000000,
    between_bytes_timeout = 60.000000,
  },
  director_req = 0x7f86fec054a0 {
    vcl_name = MA,
    type = backend {
      display_name = boot.MA,
      ipv4 = 127.0.0.1,
      port = 8000,
      hosthdr = 127.0.0.1,
      health = healthy,
      admin_health = probe, changed = 1525208143.558715,
      n_conn = 2,
    },
  },
  director_resp = director_req,
  http[bereq] = 0x7f870087a620 {
    ws = 0x7f870087a058 {
      [Already dumped, see above]
    },
    hdrs {
      \"GET\",
      \"/skin/frontend/enterprise/hndefault/js/plugins/mustache.min.js\",
      \"HTTP/1.1\",
      \"Host: local.hndev.xyz\",
      \"X-Real-IP: 127.0.0.1\",
      \"X-Forwarded-Proto: https\",
      \"SSL_OFFLOADED: true\",
      \"HTTPS: on\",
      \"Pragma: no-cache\",
      \"Cache-Control: no-cache\",
      \"User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/65.0.3325.181 Safari/537.36\",
      \"Accept: */*\",
      \"Referer: https://local.hndev.xyz/email/preferences/\",
      \"Accept-Language: en-US,en;q=0.9,ar;q=0.8\",
      \"Cookie: CACHED_FRONT_FORM_KEY=43b9gs6Hq5ufdhmX; CACHED_FRONT_FORM_KEY=43b9gs6Hq5ufdhmX; hn.cookie-notice=1; hn.site-entry=1; SHORTLIST_TOTAL_PRODUCTS=0; bfx.country=SE; bfx.currency=SEK; _ga=GA1.2.1383546762.1523484080; rskxRunCookie=0; rCookie=0mchfjlt9ybqj9aa9ihx5t; hero-transactions=[]; lastRskxRun=1524068329381; hn.customer.dept=mens; _gid=GA1.2.631503905.1525100662; hero-basket={%22line_items%22:[{%22product%22:{%22category%22:%22Men%22%2C%22subcategory%22:%22All%20Clothing%22%2C%22id%22:%22SC130318%22%2C%22sku_code%22:%22SC130318%22}%2C%22quantity%22:1%2C%22subtotal%22:665}]}; AJAXBREADCRUMBS=%5B%221843%22%2C2308%2C134%2C140%2C%22%22%5D; SHORTLIST_PRODUCT_AND_ITEM_IDS=%5B%5D; CART_ITEMS_QUANTITY=%7B%22default%22%3A0%2C%22en-hk%22%3A1%7D; cookies_populated=1; frontend=reb6v9fdomb5t939erqef10r22; CART_TOTAL=%7B%22default%22%3A%7B%22subtotal%22%3A0%2C%22grand_total%22%3A0%2C%22giftwrapping%22%3A0%7D%2C%22en-hk%22%3A%7B%22subtotal%22%3A5248.75%2C%22grand_total%22%3A5248.75%2C%22giftwrapping%22%3A0%7D%7D; CUSTOMER_LOGGED_IN=1; CUSTOMER_NUMBER=9876543210123; HN_SEGMENT=ea2c0ea1a08add3a75273e7f32f05f7a\",
      \"X-Forwarded-For: 127.0.0.1, 127.0.0.1\",
      \"X-Device: desktop\",
      \"X-Backend: MA\",
      \"X-Varnish: 69\",
    },
  },
  http[beresp] = 0x7f870087aa98 {
    ws = 0x7f870087a058 {
      [Already dumped, see above]
    },
    hdrs {
    },
  },
  objcore[fetch] = 0x7f86fee0d1f0 {
    refcnt = 2,
    flags = {busy, private},
    exp_flags = {},
    boc = 0x7f86fee0cdf0 {
      refcnt = 2,
      state = req_done,
      vary = 0x0,
      stevedore_priv = 0x0,
    },
    exp = {0.000000, 0.000000, 0.000000, 0.000000},
    objhead = 0x7f86fed02b50,
    stevedore = 0x0,
  },
  vcl = {
    name = \"boot\",
    busy = 7,
    discard = 0,
    state = auto,
    temp = warm,
    conf = {
      srcname = {
        \"/usr/local/etc/varnish/local.vcl\",
        \"Builtin\",
        \"/usr/local/etc/varnish/backend.vcl\",
        \"/usr/local/etc/varnish/mobile-detect.vcl\",
        \"/usr/local/etc/varnish/local.routing.vcl\",
      },
    },
  },
  vmods = {
  },
},


Debug: Child cleanup complete
Debug: Child (93205) Started
Info: Child (93205) said Child starts

lkarsten · 2018-05-01T21:36:28Z

Reopened to get some fresh eyes on this. I'm not running Varnish on macos these days.

snoolord · 2018-05-01T22:20:04Z

Having this issue as well on several machines but with 4.1.9. Similar error as @yousefcisco.

Last panic at: Tue, 01 May 2018 20:25:41 GMT
"Assert error in Lck_CondWait(), cache/cache_lck.c line 196:
  Condition(((*__error())) == 0) not true.
errno = 22 (Invalid argument)
thread = (cache-worker)
version = varnish-4.1.9 revision 5024f60c3a51f537279977989b645e983a946e1a
ident = Darwin,17.5.0,x86_64,-jnone,-smalloc,-smalloc,-hcritbit,kqueue
now = 139606.307215 (mono), 1525206341.817329 (real)
Backtrace:
  0x100690590: 0   varnishd                            0x0000000100690590 pan_ic + 513
  0x10068c742: 0   varnishd                            0x000000010068c742 Lck__New + 0
  0x100672c71: 0   varnishd                            0x0000000100672c71 VBT_Wait + 151
  0x10066dee0: 0   varnishd                            0x000000010066dee0 vbe_dir_gethdrs + 281
  0x1006777e2: 0   varnishd                            0x00000001006777e2 VDI_GetHdr + 102
  0x10068007b: 0   varnishd                            0x000000010068007b vbf_fetch_thread + 2681
  0x1006a91c4: 0   varnishd                            0x00000001006a91c4 WRK_Thread + 1635
  0x1006a8b03: 0   varnishd                            0x00000001006a8b03 pool_thread + 56
  0x7fff7edc4661: 0   libsystem_pthread.dylib             0x00007fff7edc4661 _pthread_body + 340
  0x7fff7edc450d: 0   libsystem_pthread.dylib             0x00007fff7edc450d _pthread_body + 0
busyobj = 0x7fbad1891020 {
  ws = 0x7fbad18910e0 {
    id = \"bo\",
    {s,f,r,e} = {0x7fbad1892f98,+200,0x0,+57440},
  },
  refcnt = 2,
  retries = 0, failed = 0, state = 1,
  flags = {do_stream, do_pass, uncacheable},
  http_conn = 0x7fbad1892fb0 {
    fd = 21,
    doclose = NULL,
    ws = 0x0,
    {rxbuf_b, rxbuf_e} = {0x0, 0x0},
    {pipeline_b, pipeline_e} = {0x0, 0x0},
    content_length = 0,
    body_status = none,
    first_byte_timeout = 60.000000,
    between_bytes_timeout = 60.000000,
  },
  director_req = 0x7fbacfc052c8 {
    vcl_name = ngts_mam,
    type = backend {
      display_name = boot.ngts_mam,
      ipv4 = 127.0.0.1,
      port = 9005,
      hosthdr = 127.0.0.1,
      health=healthy, admin_health=probe, changed=1525205710.2,
      n_conn = 1,
    },
  },
  director_resp = director_req,
  http[bereq] = 0x7fbad18916a8 {
    ws[bo] = 0x7fbad18910e0,
    hdrs {
      \"GET\",
      \"/site/compiled-assets/karbonweb-light.0a6f77c2fe15b2df818cd5c56d37ff2a.woff\",
      \"HTTP/1.1\",
      \"X-Forwarded-Proto: https\",
      \"Host: secure-wzhao-1.dev1-am.sigfig.com\",
      \"X-Remote-Addr: 127.0.0.1\",
      \"X-SSL_CLIENT_VERIFY: NONE\",
      \"Origin: https://secure-wzhao-1.dev1-am.sigfig.com\",
      \"If-None-Match: W/\"22026-x7BVjQd+rUdrlJwEr5MB2UsF2H0\"\",
      \"User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/65.0.3325.181 Safari/537.36\",
      \"Accept: */*\",
      \"Referer: https://secure-wzhao-1.dev1-am.sigfig.com/site/\",
      \"Accept-Encoding: gzip, deflate, br\",
      \"Accept-Language: en-US,en;q=0.9\",
      \"Cookie: testingBookkeeping=%7B%22Prominent%20Phone%20Campaign%22%3A%7B%22testVersion%22%3A%22hidePhone%22%2C%22refreshedDate%22%3A1525206338126%7D%7D; nv_tc=%7B%22referer%22%3A%22%22%2C%22query%22%3A%22%2Fsite%2F%23%2Fhome%2Fam%22%7D; _ga=GA1.4.1137410852.1524872946; _gid=GA1.4.22079284.1525107140; check=true; AMCVS_2DA155B058A1AEEB0A495E4F%40AdobeOrg=1; Portfolios-fakePriorDayValue=false; AdvisorModal=%7B%22startTime%22%3A1525107144.053%2C%22viewState%22%3A1%7D; s_cc=true; aam_uuid=76870132130151314612100115769176779318; fundingCardTargetDismissed=true; AdvisorModal-fam=%7B%22startTime%22%3A1525107510.967%2C%22viewState%22%3A1%7D; mptSubjectiveQuestionnaireResponse=%7B%22simpleAnswers%22%3A%22%7B%5C%22version%5C%22%3A2.9%2C%5C%22source%5C%22%3A%5C%22SIMPLE_FRONTEND%5C%22%2C%5C%22isRetirementV2%5C%22%3Atrue%2C%5C%22isTargetYield%5C%22%3Afalse%2C%5C%22isModernPortfolioTheory%5C%22%3Afalse%2C%5C%22goalBasedModels%5C%22%3A%7B%5C%22SAVE_FOR_RETIREMENT_V2%5C%22%3A%7B%5C%22ageInputModel%5C%22%3A40%2C%5C%22incomeInputModel%5C%22%3A123123%2C%5C%22currentStateSelectModel%5C%22%3A%5C%22AK%5C%22%2C%5C%22currentSettlementSelectModel%5C%22%3A%5C%22suburban%5C%22%2C%5C%22savingsRateInputModel%5C%22%3A39600%2C%5C%22savingsRatePeriodSelectModel%5C%22%3A1%2C%5C%22currentSavingsInputModel%5C%22%3A2222%7D%7D%2C%5C%22currentGoal%5C%22%3A%5C%22SAVE_FOR_RETIREMENT_V2%5C%22%2C%5C%22currentAge%5C%22%3A40%7D%22%2C%22answers%22%3A%5B%5D%2C%22source%22%3A%22SIMPLE_FRONTEND%22%7D; s_fid=21770AE2EF5799EC-3F5181EBF6A5A801; nv_ps_2=1934d2e4e0b0c255fb2202a9c9dae70a; nv_ps_1=64bb27063c993ba71e95c583a1f733d7; nv_ps_0=ce09cf73c211763b73986a90f34d5de0; PSA=d931a645699da8d061085950cdf97f7f; nv_sm=php_onlogin; __au=base64%3Ad3poYW8wNDMwMTg%3D; __dli=1525129111; nv_cplt=enabled; __utma=84501531.2124764332.1523343676.1525129153.1525129153.1; __utmc=84501531; __utmz=84501531.1525129153.1.1.utmcsr=sigfig.atlassian.net|utmccn=(referral)|utmcmd=referral|utmcct=/wiki/spaces/~kristen/blog/2018/04/30/547553676/How%20to%20create%20test%20accounts; _sp_id.9146=2ce10258028fe533.1525129153.1.1525129157.1525129153; AMCV_2DA155B058A1AEEB0A495E4F%40AdobeOrg=-1891778711%7CMCIDTS%7C17652%7CMCMID%7C76447978421684909482134454170321290423%7CMCAAMLH-1525477746%7C9%7CMCAAMB-1525805103%7CRKhpRz8krg2tLO6pguXWp5olkAcUniQYPHaMWWgdJ3xzPWQmdj0y%7CMCOPTOUT-1525207503s%7CNONE%7CvVersion%7C2.4.0%7CMCAID%7CNONE%7CMCSYNCSOP%7C411-17659; _sp_ses.9c41=*; anonGoalServMptData=%7B%22v3%22%3A%22%7B%5C%22carpo%5C%22%3Atrue%2C%5C%22rp%5C%22%3A100%2C%5C%22isSimple%5C%22%3Atrue%2C%5C%22goal%5C%22%3A%5C%22SAVE_FOR_RETIREMENT_V2%5C%22%2C%5C%22suitability%5C%22%3Atrue%2C%5C%22assumptionsOverrides%5C%22%3A%7B%5C%22riskPreference%5C%22%3Anull%2C%5C%22retirementAge%5C%22%3Anull%2C%5C%22lifeExpectancy%5C%22%3Anull%2C%5C%22salaryGrowthRate%5C%22%3Anull%2C%5C%22retirementIncomeRate%5C%22%3Anull%2C%5C%22annualInflationRate%5C%22%3Anull%2C%5C%22currentSocialSecurityPayout%5C%22%3Anull%2C%5C%22socialSecurityStartAge%5C%22%3Anull%2C%5C%22retirementReturnRate%5C%22%3Anull%2C%5C%22retirementState%5C%22%3Anull%2C%5C%22retirementSettlement%5C%22%3Anull%2C%5C%22desiredStandardOfLiving%5C%22%3A-2%7D%2C%5C%22simpleAnswers%5C%22%3A%5C%22%7B%5C%5C%5C%22version%5C%5C%5C%22%3A2.9%2C%5C%5C%5C%22source%5C%5C%5C%22%3A%5C%5C%5C%22SIMPLE_FRONTEND%5C%5C%5C%22%2C%5C%5C%5C%22isRetirementV2%5C%5C%5C%22%3Atrue%2C%5C%5C%5C%22isTargetYield%5C%5C%5C%22%3Afalse%2C%5C%5C%5C%22isModernPortfolioTheory%5C%5C%5C%22%3Afalse%2C%5C%5C%5C%22goalBasedModels%5C%5C%5C%22%3A%7B%5C%5C%5C%22SAVE_FOR_RETIREMENT_V2%5C%5C%5C%22%3A%7B%5C%5C%5C%22ageInputModel%5C%5C%5C%22%3A40%2C%5C%5C%5C%22incomeInputModel%5C%5C%5C%22%3A123123%2C%5C%5C%5C%22currentStateSelectModel%5C%5C%5C%22%3A%5C%5C%5C%22AK%5C%5C%5C%22%2C%5C%5C%5C%22currentSettlementSelectModel%5C%5C%5C%22%3A%5C%5C%5C%22suburban%5C%5C%5C%22%2C%5C%5C%5C%22savingsRateInputModel%5C%5C%5C%22%3A39600%2C%5C%5C%5C%22savingsRatePeriodSelectModel%5C%5C%5C%22%3A1%2C%5C%5C%5C%22currentSavingsInputModel%5C%5C%5C%22%3A2222%7D%7D%2C%5C%5C%5C%22currentGoal%5C%5C%5C%22%3A%5C%5C%5C%22SAVE_FOR_RETIREMENT_V2%5C%5C%5C%22%2C%5C%5C%5C%22currentAge%5C%5C%5C%22%3A40%7D%5C%22%2C%5C%22answers%5C%22%3A%5B%5D%2C%5C%22version%5C%22%3A1.4%2C%5C%22source%5C%22%3A%5C%22LEGACY_BACKEND%5C%22%7D%22%7D; s_sq=%5B%5BB%5D%5D; _gat=1; gpv=Onboarding%3AQuestionnaire%3AMadlib; tp=1363; s_ppv=Onboarding%253AQuestionnaire%253AMadlib%2C52%2C52%2C707; mbox=session#d0554ae490fd41988fa50f1420873fe1#1525208200|PC#d0554ae490fd41988fa50f1420873fe1.28_52#1588451132; _sp_id.9c41=e7a43667f57be5c2.1525206330.0.1525206342.\",
      \"X-Forwarded-For: 127.0.0.1, 127.0.0.1\",
      \"X-Varnish: 98319\",
    },
  },
  http[beresp] = 0x7fbad1891b20 {
    ws[bo] = 0x7fbad18910e0,
    hdrs {
    },
  },
  objcore[fetch] = 0x7fbacfe0ebc0 {
    refcnt = 2,
    flags = 0x10a,
    exp_flags = 0x0,
    exp = { 0.000000, 0.000000, 0.000000, 0.000000 }
    objhead = 0x7fbacff01530,
    stevedore = 0x0,
  },
  vcl = {
    busy = 11
    discard = 0,
    state = auto,
    temp = warm,
    conf = {
      srcname = {
        \"/Users/wzhao/workspace/ngts/ngts_dev_tools/varnish/local_ngts.vcl\",
        \"Builtin\",
      },
    },
  },
},

snoolord · 2018-05-01T23:38:33Z

@yousefcisco We are on the same MacOS as well I just noticed. Maybe the newest high sierra is not playing nice with Varnish.

nigoroll · 2018-05-02T09:52:29Z

Thanks for the new panic infos. The original panic info did not have errno = 22 (Invalid argument) which I guess can be a helpful clue here.

yousefcisco · 2018-05-02T16:01:56Z

I've downgraded my version of varnish and I'm still having the error. @nigoroll do you think this is a different issue?

snoolord · 2018-05-07T18:40:44Z

@nigoroll @yousefcisco I upgraded my version of varnish and I'm still getting the issue. 90% of my requests result in a 502 Gateway error through nginx

snoolord · 2018-05-23T21:54:16Z

@yousefcisco I am still having major issues @nigoroll @fgsch @bsdphk
Our front end team is at a stand still. Is there any update on this issue?

fgsch · 2018-05-24T00:05:47Z

Please note that OSX is not one of the supported platforms. See https://varnish-cache.org/docs/6.0/phk/platforms.html for details.
While some people use macos in their daily lives (e.g. me), using this in production is not a good idea.

yousefcisco · 2018-05-24T12:09:07Z

Yeah we're still having this issue as well, some members on my team are thankfully on Sierra and don't have it. Everyone on High Sierra has it constantly.

@winstonjz I reduced the frequency of this issue by getting nginx to resolve static files instead of going through varnish which worked for the most part.

The other thing in common between all three panic errors (I think we need more) is the do_stream flag, could this be related? I'm gonna run a test with this flag set to false and see if that helps.

@fgsch @nigoroll can you shed some light on what Lck_CondWait does?

nigoroll · 2018-05-24T12:14:57Z

Lck_CondWait wraps a condition variable wait. Apparently Apple has made a change which break our assumptions. @yousefcisco and @winstonjz it sounds like you might want to consider http://varnish-cache.org/business/index.html#business

yousefcisco · 2018-05-24T12:45:45Z

@nigoroll My company is already with Fastly, would their professional services team be able to resolve this issue?

FYI the do_stream test failed. It seems setting set beresp.do_stream = false; in vcl_backend_response doesn't actually remove the flag?

nigoroll · 2018-05-24T13:58:15Z

@yousefcisco I cannot answer your question, I am not fastly.
Regarding do_stream, please do not mix issues and idk what "the do_stream test" is.

yousefcisco · 2018-05-27T11:46:36Z

@nigoroll I was just going to try and see if this issue happens without the do_stream flag as that's one thing I found in common between all three panic reports. It doesn't seem to be related though.

bsdphk · 2018-06-13T06:41:59Z

Somebody needs to reproduce this and get at the core dump with a debugger to find out what is going on.

Alternatively they can stuff a bunch of VSL/printfs into their copy of the source-code.

The fact that we only see it on OS/X does not mean it's not a generic bug, any bug which can cause this would be very sensitive to both the implementation and scheduling of threads.

yohanespradono · 2018-07-31T09:23:43Z

I am getting this error on varnish 6. it seems that it does not happen with varnish v4.1.10.

bsdphk · 2019-04-23T08:07:17Z

Timing this one out

lkarsten · 2019-08-19T10:34:58Z

This is still an issue on macos mojave 10.14.5, with git master:

[..]
**** s1   txresp|HTTP/1.1 200 OK\r
**** s1   txresp|Content-Length: 4\r
**** s1   txresp|\r
**** s1   txresp|foo1
**** s1   Loop #8
**   s1   === rxreq
---- s3   HTTP rx failed (fd:21 read: Connection reset by peer)
---- s2   HTTP rx failed (fd:20 read: Connection reset by peer)
---- s1   HTTP rx failed (fd:19 read: Connection reset by peer)
**** c1   rxhdrlen = 0
---- c1   HTTP header is incomplete
**** c3   rxhdrlen = 0
---- c3   HTTP header is incomplete
**** c2   rxhdrlen = 0
---- c2   HTTP header is incomplete
*    top  RESETTING after ./tests/b00048.vtc
**   c2   Waiting for client
**   c3   Waiting for client
***  v1   debug|Error: Child (36250) died signal=6
**   s0   Waiting for server (4/-1)
**   s1   Waiting for server (-1/19)
**   s2   Waiting for server (-1/20)
**   s3   Waiting for server (-1/21)
**   v1   Wait
**** v1   CLI TX|panic.clear
**** dT   0.716
***  v1   debug|Error: Child (36250) Panic at: Mon, 19 Aug 2019 10:09:52 GMT
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 218:
***  v1   debug|  Condition(errno == 0 || errno == ETIMEDOUT || errno == EINTR) not true.
***  v1   debug|version = varnish-trunk revision f4dcf8f02a2fb059dacba4c7bedefccbe9897cd2, vrt api = 9.0
***  v1   debug|ident = Darwin,18.6.0,x86_64,-jnone,-sdefault,-sdefault,-hcritbit,poll
***  v1   debug|now = 87406.039956 (mono), 1566209392.873826 (real)
***  v1   debug|Backtrace:
***  v1   debug|  0x107835171: 0   varnishd                            0x0000000107835171 pan_backtrace + 49
***  v1   debug|  0x107834f50: 0   varnishd                            0x0000000107834f50 pan_ic + 688
***  v1   debug|  0x1078ea4d5: 0   varnishd                            0x00000001078ea4d5 VAS_Fail + 85
***  v1   debug|  0x10782e67b: 0   varnishd                            0x000000010782e67b Lck_CondWait + 699
***  v1   debug|  0x10784b695: 0   varnishd                            0x000000010784b695 VCP_Wait + 565
***  v1   debug|  0x10784b457: 0   varnishd                            0x000000010784b457 VTP_Wait + 39
***  v1   debug|  0x1077fb6b0: 0   varnishd                            0x0000000107
***  v1   debug|7fb6b0 vbe_dir_gethdrs + 1072
***  v1   debug|  0x10780a130: 0   varnishd                            0x000000010780a130 VDI_GetHdr + 416
***  v1   debug|  0x107818640: 0   varnishd                            0x0000000107818640 vbf_stp_startfetch + 1024
***  v1   debug|  0x1078172c6: 0   varnishd                            0x00000001078172c6 vbf_fetch_thread + 1638
***  v1   debug|errno = 22 (Invalid argument)
***  v1   debug|thread = (cache-worker)
***  v1   debug|thr.req = 0x0 {
***  v1   debug|},
***  v1   debug|thr.busyobj = 0x107f7e020 {
***  v1   debug|  end = 0x107f8e000,
***  v1   debug|  retries = 0,
***  v1   debug|  sp = 0x7f8abcc070f0 {
***  v1   debug|    fd = 26, vxid = 1001,
***  v1   debug|    t_open = 1566209392.659656,
***  v1   debug|    t_idle = 1566209392.873595,
***  v1   debug|    ws = 0x7f8abcc07130 {
***  v1   debug|      id = \"ses\",
***  v1   debug|      {s, f, r, e} = {0x7f8abcc07170, +96, 0x0, +344},
***  v1   debug|    },
***  v1   debug|    transport = HTTP/1 {
***  v1   debug|      state = HTTP1::Proc
***  v1   debug|    }
***  v1   debug|    client = 127.0.0.1 57489 127.0.0.1:57477,
***  v1   debug|  },
***  v1   debug|  worker = 0x700003d21df0 {
***  v1   debug|    ws = 0x700003d21e98 {
***  v1   debug|      id = \"wrk\",
***  v1   debug|      {s, f, r, e} = {0x700003d213e0, +0, 0x0, +2040},
***  v1   debug|    },
***  v1   debug|    VCL::method = BACKEND_FETCH,
***  v1   debug|    VCL::return = fetch,
***  v1   debug|    VCL::methods = {BACKEND_FETCH},
***  v1   debug|  },
***  v1   debug|
***  v1   debug|vfc = 0x107f7ff20 {
***  v1   debug|    failed = 0,
***  v1   debug|    req = 0x107f7e630,
***  v1   debug|    resp = 0x107f7eaa8,
***  v1   debug|    wrk = 0x700003d21df0,
***  v1   debug|    oc = 0x7f8abcd02bc0,
***  v1   debug|    obj_flags = 0x0,
***  v1   debug|  },
***  v1   debug|  ws = 0x107f7e060 {
***  v1   debug|    id = \"bo\",
***  v1   debug|    {s, f, r, e} = {0x107f7ff68, +192, 0x0, +57488},
***  v1   debug|  },
***  v1   debug|  ws_bo = 0x107f7ffb8,
***  v1   debug|  http[bereq] = 0x107f7e630 {
***  v1   debug|    ws = 0x107f7e060 {
***  v1   debug|      [Already dumped, see above]
***  v1   debug|    },
***  v1   debug|    hdrs {
***  v1   debug|      \"GET\",
***  v1   debug|      \"/c1\",
***  v1   debug|      \"HTTP/1.1\",
***  v1   debug|      \"Host: 127.0.0.1\",
***  v1   debug|      \"X-Forwarded-For: 127.0.0.1\",
***  v1   debug|      \"X-Varnish: 1044\",
***  v1   debug|    },
***  v1   debug|  },
***  v1   debug|  http[beresp] = 0x107f7eaa8 {
***  v1   debug|    ws = 0x107f7e060 {
***  v1   debug|      [Already dumped, see above]
***  v1   debug|    },
***  v1   debug|    hdrs {
***  v1   debug|    },
***  v1   debug|  },
***  v1   debug|  objcore[fetch] = 0x7f8abcd02bc0 {
***  v1   debug|    refcnt = 2,
***  v1   debug|    flags = {busy, private},
***  v1   debug|    exp_flags = {},
***  v1   debug|    boc = 0x7f8abcd029e0 {
***  v1   debug|      refcnt = 2,
***  v1   debug|      state = req_done,
***  v1   debug|      vary = 0x0,
***  v1   debug|      stevedore_priv = 0x0,
***  v1   debug|    },
***  v1   debug|    exp = {0.000000, 0.000000, 0.000000, 0.000000},
***  v1   debug|    objhead = 0x7f8abcc05d00,
***  v1   debug|    stevedore = 0x0,
***  v1   debug|  },
***  v1   debug|  http_conn = 0x107f7ffc8 {
***  v1   debug|    fd =
***  v1   debug| 27 (@0x7f8abce013b4),
***  v1   debug|    doclose = NULL,
***  v1   debug|    ws = 0x0 {
***  v1   debug|    },
***  v1   debug|    {rxbuf_b, rxbuf_e} = {0x0, 0x0},
***  v1   debug|    {pipeline_b, pipeline_e} = {0x0, 0x0},
***  v1   debug|    content_length = 0,
***  v1   debug|    body_status = none,
***  v1   debug|    first_byte_timeout = 60.000000,
***  v1   debug|    between_bytes_timeout = 60.000000,
***  v1   debug|  },
***  v1   debug|  flags = {do_stream, do_pass, uncacheable},
***  v1   debug|  director_req = 0x7f8abcd01f20 {
***  v1   debug|    cli_name = vcl1.s0,
***  v1   debug|    admin_health = healthy, changed = 1566209392.557024,
***  v1   debug|    type = backend {
***  v1   debug|      ipv4 = 127.0.0.1,
***  v1   debug|      port = 57471,
***  v1   debug|      hosthdr = 127.0.0.1,
***  v1   debug|      n_conn = 3,
***  v1   debug|    },
***  v1   debug|  },
***  v1   debug|  director_resp = director_req,
***  v1   debug|  vcl = {
***  v1   debug|    name = \"vcl1\",
***  v1   debug|    busy = 6,
***  v1   debug|    discard = 0,
***  v1   debug|    state = auto,
***  v1   debug|    temp = warm,
***  v1   debug|    conf = {
***  v1   debug|      syntax = \"41\",
***  v1   debug|      srcname = {
***  v1   debug|        \"<vcl.inline>\",
***  v1   debug|        \"Builtin\",
***  v1   debug|      },
***  v1   debug|    },
***  v1   debug|  },
***  v1   debug|},
***  v1   debug|vmods = {
***  v1   debug|},
***  v1   debug|
***  v1   debug|
***  v1   debug|Debug: Child cleanup complete
***  v1   CLI RX  200
---- v1   Unexpected panic
*    top  failure during reset
#    top  TEST ./tests/b00048.vtc FAILED (0.718) exit=2
FAIL tests/b00048.vtc (exit status: 2)

The following test cases are failing:

lkarsten@jungel:~/work/Varnish-Cache/bin/varnishtest$ grep ^FAIL\  test-suite.log
FAIL tests/b00048.vtc (exit status: 2)
FAIL tests/c00019.vtc (exit status: 2)
FAIL tests/c00025.vtc (exit status: 2)
FAIL tests/c00027.vtc (exit status: 2)
FAIL tests/c00045.vtc (exit status: 2)
FAIL tests/d00002.vtc (exit status: 2)
FAIL tests/d00003.vtc (exit status: 2)
FAIL tests/r00425.vtc (exit status: 2)
FAIL tests/r00861.vtc (exit status: 2)
FAIL tests/r00961.vtc (exit status: 2)
FAIL tests/r01030.vtc (exit status: 2)
FAIL tests/r01120.vtc (exit status: 2)
FAIL tests/r01168.vtc (exit status: 2)
FAIL tests/r01781.vtc (exit status: 2)
FAIL tests/r02372.vtc (exit status: 2)
FAIL tests/r02700.vtc (exit status: 2)
FAIL tests/v00050.vtc (exit status: 2)

bsdphk · 2019-08-22T07:44:39Z

I have added an assert on the ts_nsec field to make sure it is valid.

I'm pretty sure we're not guilty of this one: https://wiki.sei.cmu.edu/confluence/pages/viewpage.action?pageId=87151984 but that is probably my best guess by now.

lkarsten · 2019-08-22T08:07:17Z

Hi.

Re-ran with latest master now, I'm afraid it is the same assert that is triggering:

lkarsten@jungel:~/work/Varnish-Cache$ grep Assert bin/varnishtest/test-suite.log
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
lkarsten@jungel:~/work/Varnish-Cache$ grep Assert bin/varnishtest/test-suite.log  | wc -l
      13

lkarsten@jungel:~/work/Varnish-Cache$ grep ^FAIL\   bin/varnishtest/test-suite.log | sort
FAIL tests/c00004.vtc (exit status: 2)
FAIL tests/c00045.vtc (exit status: 2)
FAIL tests/c00060.vtc (exit status: 2)
FAIL tests/c00072.vtc (exit status: 2)
FAIL tests/d00002.vtc (exit status: 2)
FAIL tests/d00003.vtc (exit status: 2)
FAIL tests/e00017.vtc (exit status: 2)
FAIL tests/r00425.vtc (exit status: 2)
FAIL tests/r02042.vtc (exit status: 2)
FAIL tests/r02219.vtc (exit status: 2)
FAIL tests/r02372.vtc (exit status: 2)
FAIL tests/r03006.vtc (exit status: 2)
FAIL tests/v00043.vtc (exit status: 2)

b00048.vtc didn't fail this time. Pasting backtrace from c00004.vtc, in case you/someone can spot something different this time around:

**** v1   CLI TX|panic.clear
***  v1   debug|Error: Child (14361) died signal=6
**** dT   0.546
***  v1   debug|Error: Child (14361) Panic at: Thu, 22 Aug 2019 07:50:26 GMT
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
***  v1   debug|  Condition(errno == 0 || errno == ETIMEDOUT || errno == EINTR) not true.
***  v1   debug|version = varnish-trunk revision eed8289377394440c6c111f431f031735485d5ac, vrt api = 9.0
***  v1   debug|ident = Darwin,18.6.0,x86_64,-jnone,-sdefault,-sdefault,-hcritbit,kqueue
***  v1   debug|now = 338240.331741 (mono), 1566460226.563716 (real)
***  v1   debug|Backtrace:
***  v1   debug|  0x10340a0a1: 0   varnishd                            0x000000010340a0a1 pan_backtrace + 49
***  v1   debug|  0x103409e80: 0   varnishd                            0x0000000103409e80 pan_ic + 688
***  v1   debug|  0x1034bf4a5: 0   varnishd                            0x00000001034bf4a5 VAS_Fail + 85
***  v1   debug|  0x1034035ae: 0   varnishd                            0x00000001034035ae Lck_CondWait + 766
***  v1   debug|  0x1034205c5: 0   varnishd                            0x00000001034205c5 VCP_Wait + 565
***  v1   debug|  0x103420387: 0   varnishd                            0x0000000103420387 VTP_Wait + 39
***  v1   debug|  0x1033d05a0: 0   varnishd                            0x0000000
***  v1   debug|1033d05a0 vbe_dir_gethdrs + 1072
***  v1   debug|  0x1033df020: 0   varnishd                            0x00000001033df020 VDI_GetHdr + 416
***  v1   debug|  0x1033ed530: 0   varnishd                            0x00000001033ed530 vbf_stp_startfetch + 1024
***  v1   debug|  0x1033ec1b6: 0   varnishd                            0x00000001033ec1b6 vbf_fetch_thread + 1638
***  v1   debug|errno = 22 (Invalid argument)
***  v1   debug|thread = (cache-worker)
***  v1   debug|thr.req = 0x0 {
***  v1   debug|},
***  v1   debug|thr.busyobj = 0x103b23020 {
***  v1   debug|  end = 0x103b33000,
***  v1   debug|  retries = 0,
***  v1   debug|  sp = 0x7ffa6bf02050 {
***  v1   debug|    fd = 26, vxid = 1000,
***  v1   debug|    t_open = 1566460226.537500,
***  v1   debug|    t_idle = 1566460226.563487,
***  v1   debug|    ws = 0x7ffa6bf02090 {
***  v1   debug|      id = \"ses\",
***  v1   debug|      {s, f, r, e} = {0x7ffa6bf020d0, +96, 0x0, +344},
***  v1   debug|    },
***  v1   debug|    transport = HTTP/1 {
***  v1   debug|      state = HTTP1::Proc
***  v1   debug|    }
***  v1   debug|    client = 127.0.0.1 63370 127.0.0.1:63349,
***  v1   debug|  },
***  v1   debug|  worker = 0x700002f4cdf0 {
***  v1   debug|    ws = 0x700002f4ce98 {
***  v1   debug|      id = \"wrk\",
***  v1   debug|      {s, f, r, e} = {0x700002f4c3e0, +0, 0x0, +2040},
***  v1   debug|    },
***  v1   debug|    VCL::method = BACKEND_FETCH,
***  v1   debug|    VCL::return = fetch,
***  v1   debug|    VCL::methods = {BACKEND_FETCH},
***  v1   debug|  },
***  v1   debug|
***  v1   debug|  vfc = 0x103b24f20 {
***  v1   debug|    failed = 0,
***  v1   debug|    req = 0x103b23630,
***  v1   debug|    resp = 0x103b23aa8,
***  v1   debug|    wrk = 0x700002f4cdf0,
***  v1   debug|    oc = 0x7ffa6bf027d0,
***  v1   debug|    obj_flags = 0x0,
***  v1   debug|  },
***  v1   debug|  ws = 0x103b23060 {
***  v1   debug|    id = \"bo\",
***  v1   debug|    {s, f, r, e} = {0x103b24f68, +232, 0x0, +57488},
***  v1   debug|  },
***  v1   debug|  ws_bo = 0x103b24fe0,
***  v1   debug|  http[bereq] = 0x103b23630 {
***  v1   debug|    ws = 0x103b23060 {
***  v1   debug|      [Already dumped, see above]
***  v1   debug|    },
***  v1   debug|    hdrs {
***  v1   debug|      \"GET\",
***  v1   debug|      \"/\",
***  v1   debug|      \"HTTP/1.1\",
***  v1   debug|      \"Foobar: 3\",
***  v1   debug|      \"Host: 127.0.0.1\",
***  v1   debug|      \"X-Forwarded-For: 127.0.0.1\",
***  v1   debug|      \"Accept-Encoding: gzip\",
***  v1   debug|      \"X-Varnish: 1006\",
***  v1   debug|    },
***  v1   debug|  },
***  v1   debug|  http[beresp] = 0x103b23aa8 {
***  v1   debug|    ws = 0x103b23060 {
***  v1   debug|      [Already dumped, see above]
***  v1   debug|    },
***  v1   debug|    hdrs {
***  v1   debug|    },
***  v1   debug|  },
***  v1   debug|  objcore[fetch] = 0x7ffa6bf027d0 {
***  v1   debug|    refcnt = 2,
***  v1   debug|    flags = {busy},
***  v1   debug|    exp_flags = {},
***  v1   debug|    boc = 0x7ffa6bf02880 {
***  v1   debug|      refcnt = 2,
***  v1   debug|      state = req_done,
***  v1   debug|      vary = 0x7ffa6bd034b0,
***  v1   debug|      stevedore_priv = 0x0,
***  v1   debug|    },
***  v1   debug|    exp = {0.000000, 0.000000, 0.000000, 0.000000},
***  v1   debug|    objhead = 0x7ffa6bf02570,
***  v1   debug|    s
***  v1   debug|tevedore = 0x0,
***  v1   debug|  },
***  v1   debug|  http_conn = 0x103b24ff0 {
***  v1   debug|    fd = 27 (@0x7ffa6be01d34),
***  v1   debug|    doclose = NULL,
***  v1   debug|    ws = 0x0 {
***  v1   debug|    },
***  v1   debug|    {rxbuf_b, rxbuf_e} = {0x0, 0x0},
***  v1   debug|    {pipeline_b, pipeline_e} = {0x0, 0x0},
***  v1   debug|    content_length = 0,
***  v1   debug|    body_status = none,
***  v1   debug|    first_byte_timeout = 60.000000,
***  v1   debug|    between_bytes_timeout = 60.000000,
***  v1   debug|  },
***  v1   debug|  flags = {do_stream},
***  v1   debug|  director_req = 0x7ffa6bd03ba0 {
***  v1   debug|    cli_name = vcl1.s1,
***  v1   debug|    admin_health = healthy, changed = 1566460226.434659,
***  v1   debug|    type = backend {
***  v1   debug|      ipv4 = 127.0.0.1,
***  v1   debug|      port = 63347,
***  v1   debug|      hosthdr = 127.0.0.1,
***  v1   debug|      n_conn = 1,
***  v1   debug|    },
***  v1   debug|  },
***  v1   debug|  director_resp = director_req,
***  v1   debug|  vcl = {
***  v1   debug|    name = \"vcl1\",
***  v1   debug|    busy = 2,
***  v1   debug|    discard = 0,
***  v1   debug|    state = auto,
***  v1   debug|    temp = warm,
***  v1   debug|    conf = {
***  v1   debug|      syntax = \"41\",
***  v1   debug|      srcname = {
***  v1   debug|        \"<vcl.inline>\",
***  v1   debug|        \"Builtin\",
***  v1   debug|      },
***  v1   debug|    },
***  v1   debug|  },
***  v1   debug|},
***  v1   debug|vmods = {
***  v1   debug|},
***  v1   debug|
***  v1   debug|
**** dT   0.547
***  v1   debug|Debug: Child cleanup complete
***  v1   CLI RX  200
---- v1   Unexpected panic
*    top  failure during reset
#    top  TEST ./tests/c00004.vtc FAILED (0.548) exit=2
FAIL tests/c00004.vtc (exit status: 2)

lkarsten · 2019-11-11T08:38:35Z

Re-running with current master, on macos mojave 10.14.5, the problem is still there.

There may be value in checking this on macos catalina/10.15.0, but that is still breaking lots of apps around so I haven't upgraded.

Tests that fail are: b00013 b00035 b00048 c00008 c00027 d00002 e00026 e00031 g00007 r00476 r00612 r00984 r01038 r01123 r01442 r01637 r01764 r02372 s00000

Sample from failing c00008.vtc:

***  v1   debug|Error: Child (17426) Panic at: Mon, 11 Nov 2019 08:12:42 GMT
***  v1   debug|Assert error in Lck_CondWait(), cache/cache_lck.c line 219:
***  v1   debug|  Condition(errno == 0 || errno == ETIMEDOUT || errno == EINTR) not true.
***  v1   debug|version = varnish-trunk revision 0496921fea70bb6470c52082efb520cf9a2cf3d1, vrt api = 10.0
***  v1   debug|ident = Darwin,18.6.0,x86_64,-jnone,-sdefault,-sdefault,-hcritbit,kqueue
***  v1   debug|now = 585967.780047 (mono), 1573459962.869593 (real)
***  v1   debug|Backtrace:
***  v1   debug|  0x1082c6b71: 0   varnishd                            0x00000001082c6b71 pan_backtrace + 49
***  v1   debug|  0x1082c6950: 0   varnishd                            0x00000001082c6950 pan_ic + 688
***  v1   debug|  0x10837c1b5: 0   varnishd                            0x000000010837c1b5 VAS_Fail + 85
***  v1   debug|  0x1082c002e: 0   varnishd                            0x00000001082c002e Lck_CondWait + 766
***  v1   debug|  0x1082dd385: 0   varnishd                            0x00000001082dd385 VCP_Wait + 565
***  v1   debug|  0x1082dd147: 0   varnishd                            0x00000001082dd147 VTP_Wait + 39
***  v1   debug|  0x10828ccc0: 0   varnishd                            0x000000
***  v1   debug|010828ccc0 vbe_dir_gethdrs + 1072
***  v1   debug|  0x10829b710: 0   varnishd                            0x000000010829b710 VDI_GetHdr + 416
***  v1   debug|  0x1082a9e80: 0   varnishd                            0x00000001082a9e80 vbf_stp_startfetch + 1024
***  v1   debug|  0x1082a8b16: 0   varnishd                            0x00000001082a8b16 vbf_fetch_thread + 1638
***  v1   debug|errno = 22 (Invalid argument)
***  v1   debug|thread = (cache-worker)
***  v1   debug|thr.req = 0x0 {
***  v1   debug|},
***  v1   debug|thr.busyobj = 0x1089e3020 {
***  v1   debug|  end = 0x1089f3000,
***  v1   debug|  retries = 0,
***  v1   debug|  sp = 0x7fe9b0e02830 {
***  v1   debug|    fd = 23, vxid = 1000,
***  v1   debug|    t_open = 1573459962.852305,
***  v1   debug|    t_idle = 1573459962.868538,
***  v1   debug|    ws = 0x7fe9b0e02870 {
***  v1   debug|      id = \"ses\",
***  v1   debug|      {s, f, r, e} = {0x7fe9b0e028b0, +96, 0x0, +344},
***  v1   debug|    },
***  v1   debug|    transport = HTTP/1 {
***  v1   debug|      state = HTTP1::Proc
***  v1   debug|    }
***  v1   debug|    client = 127.0.0.1 55194 127.0.0.1:55179,
***  v1   debug|  },
***  v1   debug|  worker = 0x70000d1a6df0 {
***  v1   debug|    ws = 0x70000d1a6e98 {
***  v1   debug|      id = \"wrk\",
***  v1   debug|      {s, f, r, e} = {0x70000d1a63e0, +0, 0x0, +2040},
***  v1   debug|    },
***  v1   debug|    VCL::method = BACKEND_FETCH,
***  v1   debug|    VCL::return = 0x0,
***  v1   debug|    VCL::methods = {BACKEND_FETCH},
***  v1   debug|  },
***  v1   debug|  vfc = 0x1089e4f18 {
***  v1   debug|    failed = 0,
***  v1   debug|    req = 0x1089e3628,
***  v1   debug|    resp = 0x1089e3aa0,
***  v1   debug|    wrk = 0x70000d1a6df0,
***  v1   debug|    oc = 0x7fe9b0f00fa0,
***  v1   debug|    obj_flags = 0x0,
***  v1   debug|  },
***  v1   debug|  ws = 0x1089e3060 {
***  v1   debug|    id = \"bo\",
***  v1   debug|    {s, f, r, e} = {0x1089e4f60, +216, 0x0, +57496},
***  v1   debug|  },
***  v1   debug|  ws_bo = 0x1089e4fc8,
***  v1   debug|  http[bereq] = 0x1089e3628 {
***  v1   debug|    ws = 0x1089e3060 {
***  v1   debug|      [Already dumped, see above]
***  v1   debug|    },
***  v1   debug|    hdrs {
***  v1   debug|      \"GET\",
***  v1   debug|      \"/bar\",
***  v1   debug|      \"HTTP/1.1\",
***  v1   debug|      \"X-Forwarded-For: 127.0.0.1\",
***  v1   debug|      \"host: 127.0.0.1\",
***  v1   debug|      \"Accept-Encoding: gzip\",
***  v1   debug|      \"X-Varnish: 1007\",
***  v1   debug|    },
***  v1   debug|  },
***  v1   debug|  http[beresp] = 0x1089e3aa0 {
***  v1   debug|    ws = 0x1089e3060 {
***  v1   debug|      [Already dumped, see above]
***  v1   debug|    },
***  v1   debug|    hdrs {
***  v1   debug|    },
***  v1   debug|  },
***  v1   debug|  objcore[fetch] = 0x7fe9b0f00fa0 {
***  v1   debug|    refcnt = 2,
***  v1   debug|    flags = {busy},
***  v1   debug|    exp_flags = {},
***  v1   debug|    boc = 0x7fe9b0f00df0 {
***  v1   debug|      refcnt = 2,
***  v1   debug|      state = req_done,
***  v1   debug|      vary = 0x0,
***  v1   debug|      stevedore_priv = 0x0,
***  v1   debug|    },
***  v1   debug|    exp = {0.000000, 0.000000, 0.000000, 0.000000},
***  v1   debug|    objhead = 0x7fe9b0f008d0,
***  v1   debug|    stevedore = 0x0,
***  v1   debug|  },
***  v1   debug|  http_co
***  v1   debug|nn = 0x1089e4fd8 {
***  v1   debug|    fd = 27 (@0x7fe9b0d04a94),
***  v1   debug|    doclose = NULL,
***  v1   debug|    ws = 0x0 {
***  v1   debug|    },
***  v1   debug|    {rxbuf_b, rxbuf_e} = {0x0, 0x0},
***  v1   debug|    {pipeline_b, pipeline_e} = {0x0, 0x0},
***  v1   debug|    content_length = 0,
***  v1   debug|    body_status = none,
***  v1   debug|    first_byte_timeout = 60.000000,
***  v1   debug|    between_bytes_timeout = 60.000000,
***  v1   debug|  },
***  v1   debug|  flags = {do_stream},
***  v1   debug|  director_req = 0x7fe9b0d044b0 {
***  v1   debug|    cli_name = vcl1.s1,
***  v1   debug|    admin_health = healthy, changed = 1573459962.750314,
***  v1   debug|    type = backend {
***  v1   debug|      ipv4 = 127.0.0.1,
***  v1   debug|      port = 55174,
***  v1   debug|      hosthdr = 127.0.0.1,
***  v1   debug|      n_conn = 1,
***  v1   debug|    },
***  v1   debug|  },
***  v1   debug|  director_resp = director_req,
***  v1   debug|  vcl = {
***  v1   debug|    name = \"vcl1\",
***  v1   debug|    busy = 2,
***  v1   debug|    discard = 0,
***  v1   debug|    state = auto,
***  v1   debug|    temp = warm,
***  v1   debug|    conf = {
***  v1   debug|      syntax = \"41\",
***  v1   debug|      srcname = {
***  v1   debug|        \"<vcl.inline>\",
***  v1   debug|        \"Builtin\",
***  v1   debug|      },
***  v1   debug|    },
***  v1   debug|  },
***  v1   debug|},
***  v1   debug|vmods = {
***  v1   debug|},
***  v1   debug|
***  v1   debug|Debug: Child cleanup complete

nigoroll · 2020-01-15T09:17:48Z

pow-wow: will have another look

nigoroll · 2020-01-15T12:09:23Z

FYI: https://opensource.apple.com/source/libpthread/libpthread-330.250.2/src/pthread_cond.c.auto.html (still need to check with enough time)

nigoroll · 2020-01-21T14:05:37Z

can anyone confirm that the issue is in fact fixed?
I have spent some time with someone inside apple to reproduce it and failed so far, but I also still do not have on own dev environment on macos.

gquintard · 2020-01-21T15:48:39Z

is the travis setup helpful here?

nigoroll · 2020-01-21T17:05:42Z

travis is helpful, but I checked the builds before and after e5e545f and saw no difference.

like the sign is wrong, we should never get EINVAL if the deadline is in the future. Fix the test to make sense, and hope for the best (or a M1 :-) Spotted by: Rasmus Villemoes

nigoroll closed this as completed Jun 16, 2016

vssync added the backport-review-4.1 label Jun 16, 2016

lkarsten removed the backport-review-4.1 label Jun 27, 2016

lkarsten reopened this May 1, 2018

bsdphk added the a=help wanted label Jun 13, 2018

fgsch self-assigned this Jan 18, 2019

bsdphk closed this as completed Apr 23, 2019

lkarsten reopened this Aug 19, 2019

fgsch removed their assignment Aug 19, 2019

bsdphk added a commit that referenced this issue Aug 22, 2019

Add an assert to try to catch #1853

eed8289

bsdphk mentioned this issue Sep 2, 2019

cache_lck: pthread_cond_timedwait can also returns EINVAL #3048

Closed

nigoroll self-assigned this Jan 15, 2020

bsdphk closed this as completed in e5e545f Jan 20, 2020

fwsGonzo pushed a commit to fwsGonzo/varnish-cache that referenced this issue Mar 27, 2020

Add an assert to try to catch varnishcache#1853

c7298ae

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Assert error in Lck_CondWait(), cache/cache_lck.c line 203 (on Mac OS X) #1853

Assert error in Lck_CondWait(), cache/cache_lck.c line 203 (on Mac OS X) #1853

bsdphk commented Mar 4, 2016

nigoroll commented Jun 16, 2016

nigoroll commented Jun 16, 2016

lkarsten commented Jun 27, 2016

lkarsten commented Jun 28, 2016

yousefcisco commented May 1, 2018 •

edited

lkarsten commented May 1, 2018

snoolord commented May 1, 2018 •

edited

snoolord commented May 1, 2018

nigoroll commented May 2, 2018

yousefcisco commented May 2, 2018

snoolord commented May 7, 2018

snoolord commented May 23, 2018

fgsch commented May 24, 2018 •

edited

yousefcisco commented May 24, 2018

nigoroll commented May 24, 2018 •

edited

yousefcisco commented May 24, 2018 •

edited

nigoroll commented May 24, 2018 •

edited

yousefcisco commented May 27, 2018

bsdphk commented Jun 13, 2018

yohanespradono commented Jul 31, 2018 •

edited

bsdphk commented Apr 23, 2019

lkarsten commented Aug 19, 2019

bsdphk commented Aug 22, 2019

lkarsten commented Aug 22, 2019

lkarsten commented Nov 11, 2019

nigoroll commented Jan 15, 2020

nigoroll commented Jan 15, 2020

nigoroll commented Jan 21, 2020

gquintard commented Jan 21, 2020

nigoroll commented Jan 21, 2020

Assert error in Lck_CondWait(), cache/cache_lck.c line 203 (on Mac OS X) #1853

Assert error in Lck_CondWait(), cache/cache_lck.c line 203 (on Mac OS X) #1853

Comments

bsdphk commented Mar 4, 2016

nigoroll commented Jun 16, 2016

nigoroll commented Jun 16, 2016

lkarsten commented Jun 27, 2016

lkarsten commented Jun 28, 2016

yousefcisco commented May 1, 2018 • edited

lkarsten commented May 1, 2018

snoolord commented May 1, 2018 • edited

snoolord commented May 1, 2018

nigoroll commented May 2, 2018

yousefcisco commented May 2, 2018

snoolord commented May 7, 2018

snoolord commented May 23, 2018

fgsch commented May 24, 2018 • edited

yousefcisco commented May 24, 2018

nigoroll commented May 24, 2018 • edited

yousefcisco commented May 24, 2018 • edited

nigoroll commented May 24, 2018 • edited

yousefcisco commented May 27, 2018

bsdphk commented Jun 13, 2018

yohanespradono commented Jul 31, 2018 • edited

bsdphk commented Apr 23, 2019

lkarsten commented Aug 19, 2019

bsdphk commented Aug 22, 2019

lkarsten commented Aug 22, 2019

lkarsten commented Nov 11, 2019

nigoroll commented Jan 15, 2020

nigoroll commented Jan 15, 2020

nigoroll commented Jan 21, 2020

gquintard commented Jan 21, 2020

nigoroll commented Jan 21, 2020

yousefcisco commented May 1, 2018 •

edited

snoolord commented May 1, 2018 •

edited

fgsch commented May 24, 2018 •

edited

nigoroll commented May 24, 2018 •

edited

yousefcisco commented May 24, 2018 •

edited

nigoroll commented May 24, 2018 •

edited

yohanespradono commented Jul 31, 2018 •

edited