Page MenuHomePhabricator
Create Task
Maniphest T253093

varnish-frontend-fetcherr: Assert error in vslc_vtx_next, 100% CPU usage
Closed, ResolvedPublic
Actions

Description

On all text@esams hosts, varnish-frontend-fetcherr is currently using 100% of one CPU core. There's this in the journal:

May 11 20:12:35 cp3058 varnish-frontend-fetcherr[26530]: Assert error in vslc_vtx_next(), vsl_dispatch.c line 285:
May 11 20:12:35 cp3058 varnish-frontend-fetcherr[26530]:   Condition(c->offset <= c->vtx->len) not true.

That looks like output from varnishlog, which is executed by BaseVarnishLogConsumer. We likely need to add some sort of error handling to main().

Details

SubjectRepoBranchLines +/-
varnish: unify vsl_size to new defaultoperations/puppetproduction+2 -8
varnish: bump size of varnish shared memory log to 160M (eqiad)operations/puppetproduction+1 -0
varnish: bump size of varnish shared memory log to 160M (codfw)operations/puppetproduction+1 -0
varnish: bump size of varnish shared memory log to 160M (drmrs)operations/puppetproduction+1 -0
varnish: bump size of varnish shared memory log to 160M (esams)operations/puppetproduction+1 -0
varnish: bump size of varnish shared memory log to 160M (ulsfo)operations/puppetproduction+1 -0
varnish: bump size of varnish shared memory log to 160Moperations/puppetproduction+9 -0
varnishlog: exit if process terminatesoperations/puppetproduction+5 -2
Customize query in gerrit

Event Timeline

• ema created this task.May 19 2020, 7:12 AM
Restricted Application added a project: SRE. · View Herald TranscriptMay 19 2020, 7:12 AM
Restricted Application added a subscriber: Aklapper. · View Herald Transcript
• ema triaged this task as Medium priority.May 19 2020, 7:13 AM
• ema moved this task from Backlog to Caching on the Traffic board.
gerritbot added a comment.May 19 2020, 8:27 AM

Change 597225 had a related patch set uploaded (by Ema; owner: Ema):
[operations/puppet@production] varnishlog: exit if process terminates

https://gerrit.wikimedia.org/r/597225

gerritbot added a project: Patch-For-Review.May 19 2020, 8:27 AM
gerritbot added a comment.May 19 2020, 8:37 AM

Change 597225 merged by Ema:
[operations/puppet@production] varnishlog: exit if process terminates

https://gerrit.wikimedia.org/r/597225

• ema closed this task as Resolved.May 19 2020, 8:50 AM
• ema claimed this task.

Checking poll() and exiting when it returns something else than None seems to have fixed things. Tested by shooting varnishlog on cp3056:

May 19 08:46:12 cp3056 systemd[1]: varnish-frontend-fetcherr.service: Main process exited, code=exited, status=245/n/a
May 19 08:46:12 cp3056 systemd[1]: varnish-frontend-fetcherr.service: Failed with result 'exit-code'.
May 19 08:46:12 cp3056 systemd[1]: varnish-frontend-fetcherr.service: Consumed 10.113s CPU time.
May 19 08:46:17 cp3056 systemd[1]: varnish-frontend-fetcherr.service: Service RestartSec=5s expired, scheduling restart.
May 19 08:46:17 cp3056 systemd[1]: varnish-frontend-fetcherr.service: Scheduled restart job, restart counter is at 1.
May 19 08:46:17 cp3056 systemd[1]: Stopped Varnish frontend Fetch Errors.
May 19 08:46:17 cp3056 systemd[1]: varnish-frontend-fetcherr.service: Consumed 10.113s CPU time.
May 19 08:46:17 cp3056 systemd[1]: Started Varnish frontend Fetch Errors.
Maintenance_bot removed a project: Patch-For-Review.May 19 2020, 9:10 AM
ssingh reopened this task as Open.Apr 6 2023, 3:02 PM
ssingh subscribed.
Apr 06 14:27:14 cp3064 varnishkafka[1513247]:   Condition(c->offset <= c->vtx->len) not true.
Apr 06 14:27:14 cp3064 systemd[1]: varnishkafka-eventlogging.service: Main process exited, code=killed, status=6/ABRT
Apr 06 14:27:14 cp3064 systemd[1]: varnishkafka-eventlogging.service: Failed with result 'signal'.
Apr 06 14:27:15 cp3064 systemd[1]: varnishkafka-eventlogging.service: Scheduled restart job, restart counter is at 5.
Apr 06 14:27:15 cp3064 systemd[1]: Stopped VarnishKafka eventlogging.
Apr 06 14:27:15 cp3064 systemd[1]: Started VarnishKafka eventlogging.
Apr 06 14:27:15 cp3064 varnishkafka[1513293]: Log overrun
Apr 06 14:27:15 cp3064 varnishkafka[1513293]: Log reacquired
Apr 06 14:27:15 cp3064 varnishkafka[1513293]: Log overrun
Apr 06 14:27:16 cp3064 varnishkafka[1513293]: Log reacquired
Apr 06 14:27:16 cp3064 varnishkafka[1513293]: Log overrun
Apr 06 14:27:16 cp3064 varnishkafka[1513293]: Log reacquired
Apr 06 14:27:16 cp3064 varnishkafka[1513293]: Assert error in vslc_vtx_next(), vsl_dispatch.c line 290:
Apr 06 14:27:16 cp3064 varnishkafka[1513293]:   Condition(c->offset <= c->vtx->len) not true.
Apr 06 14:27:16 cp3064 systemd[1]: varnishkafka-eventlogging.service: Main process exited, code=killed, status=6/ABRT
Apr 06 14:27:16 cp3064 systemd[1]: varnishkafka-eventlogging.service: Failed with result 'signal'.
Apr 06 14:27:16 cp3064 systemd[1]: varnishkafka-eventlogging.service: Scheduled restart job, restart counter is at 6.
Apr 06 14:27:16 cp3064 systemd[1]: Stopped VarnishKafka eventlogging.
Apr 06 14:27:16 cp3064 systemd[1]: varnishkafka-eventlogging.service: Start request repeated too quickly.
Apr 06 14:27:16 cp3064 systemd[1]: varnishkafka-eventlogging.service: Failed with result 'signal'.
Apr 06 14:27:16 cp3064 systemd[1]: Failed to start VarnishKafka eventlogging.
Apr 06 14:31:06 cp3064 systemd[1]: Started VarnishKafka eventlogging.

This happened today again, so we should probably check the reason for the resurgence of this error.

Aklapper removed • ema as the assignee of this task.Apr 10 2023, 8:47 AM

Removing inactive task assignee as this task got reopened after 3 years

BCornwall subscribed.Apr 10 2023, 5:31 PM
gerritbot added a comment.Apr 19 2023, 2:35 PM

Change 910005 had a related patch set uploaded (by Ssingh; author: Ssingh):

[operations/puppet@production] varnish: bump size of varnish shared memory log to 160M

https://gerrit.wikimedia.org/r/910005

gerritbot added a project: Patch-For-Review.Apr 19 2023, 2:35 PM
gerritbot added a comment.Apr 20 2023, 2:58 PM

Change 910005 merged by Ssingh:

[operations/puppet@production] varnish: bump size of varnish shared memory log to 160M

https://gerrit.wikimedia.org/r/910005

Maintenance_bot removed a project: Patch-For-Review.Apr 20 2023, 3:16 PM
BCornwall moved this task from Caching to Backlog on the Traffic board.Apr 26 2023, 7:15 PM
BCornwall assigned this task to ssingh.Apr 26 2023, 7:26 PM
BCornwall removed a project: SRE.
BCornwall moved this task from Backlog to Traffic team actively servicing on the Traffic board.
gerritbot added a comment.May 8 2023, 2:22 PM

Change 917346 had a related patch set uploaded (by Ssingh; author: Ssingh):

[operations/puppet@production] varnish: bump size of varnish shared memory log to 160M (ulsfo)

https://gerrit.wikimedia.org/r/917346

gerritbot added a project: Patch-For-Review.May 8 2023, 2:22 PM
gerritbot added a comment.May 8 2023, 2:32 PM

Change 917346 merged by Ssingh:

[operations/puppet@production] varnish: bump size of varnish shared memory log to 160M (ulsfo)

https://gerrit.wikimedia.org/r/917346

Stashbot added a comment.May 8 2023, 2:37 PM

Mentioned in SAL (#wikimedia-operations) [2023-05-08T14:37:05Z] <sukhe> sudo cumin -b1 -s1200 'A:cp and A:ulsfo' 'varnish-frontend-restart': T253093

Maintenance_bot removed a project: Patch-For-Review.May 8 2023, 3:12 PM
gerritbot added a comment.May 9 2023, 1:22 PM

Change 917878 had a related patch set uploaded (by Ssingh; author: Ssingh):

[operations/puppet@production] varnish: bump size of varnish shared memory log to 160M (esams)

https://gerrit.wikimedia.org/r/917878

gerritbot added a project: Patch-For-Review.May 9 2023, 1:22 PM
gerritbot added a comment.May 9 2023, 1:38 PM

Change 917878 merged by Ssingh:

[operations/puppet@production] varnish: bump size of varnish shared memory log to 160M (esams)

https://gerrit.wikimedia.org/r/917878

Stashbot added a comment.May 9 2023, 1:42 PM

Mentioned in SAL (#wikimedia-operations) [2023-05-09T13:42:54Z] <sukhe> sudo cumin -b1 -s1200 'A:cp and A:esams' 'varnish-frontend-restart: T253093

Maintenance_bot removed a project: Patch-For-Review.May 9 2023, 2:11 PM
gerritbot added a comment.May 10 2023, 2:58 PM

Change 918507 had a related patch set uploaded (by Ssingh; author: Ssingh):

[operations/puppet@production] varnish: bump size of varnish shared memory log to 160M (drmrs)

https://gerrit.wikimedia.org/r/918507

gerritbot added a project: Patch-For-Review.May 10 2023, 2:58 PM
gerritbot added a comment.May 10 2023, 3:58 PM

Change 918507 merged by Ssingh:

[operations/puppet@production] varnish: bump size of varnish shared memory log to 160M (drmrs)

https://gerrit.wikimedia.org/r/918507

Stashbot added a comment.May 10 2023, 4:02 PM

Mentioned in SAL (#wikimedia-operations) [2023-05-10T16:02:20Z] <sukhe> sudo cumin -b1 -s1200 'A:cp and A:drmrs' 'varnish-frontend-restart': T253093

Maintenance_bot removed a project: Patch-For-Review.May 10 2023, 4:10 PM
gerritbot added a comment.May 11 2023, 2:05 PM

Change 919074 had a related patch set uploaded (by Ssingh; author: Ssingh):

[operations/puppet@production] varnish: bump size of varnish shared memory log to 160M (codfw)

https://gerrit.wikimedia.org/r/919074

gerritbot added a project: Patch-For-Review.May 11 2023, 2:05 PM
gerritbot added a comment.May 11 2023, 2:13 PM

Change 919074 merged by Ssingh:

[operations/puppet@production] varnish: bump size of varnish shared memory log to 160M (codfw)

https://gerrit.wikimedia.org/r/919074

Stashbot added a comment.May 11 2023, 2:14 PM

Mentioned in SAL (#wikimedia-operations) [2023-05-11T14:14:58Z] <sukhe> sudo cumin -b1 -s1200 'A:cp and A:codfw' 'varnish-frontend-restart': T253093

Maintenance_bot removed a project: Patch-For-Review.May 11 2023, 2:30 PM
gerritbot added a comment.May 12 2023, 1:18 PM

Change 919327 had a related patch set uploaded (by Ssingh; author: Ssingh):

[operations/puppet@production] varnish: bump size of varnish shared memory log to 160M (eqiad)

https://gerrit.wikimedia.org/r/919327

gerritbot added a project: Patch-For-Review.May 12 2023, 1:18 PM

Change 919327 merged by Ssingh:

[operations/puppet@production] varnish: bump size of varnish shared memory log to 160M (eqiad)

https://gerrit.wikimedia.org/r/919327

Stashbot added a comment.May 12 2023, 1:22 PM

Mentioned in SAL (#wikimedia-operations) [2023-05-12T13:22:45Z] <sukhe> sudo cumin -b1 -s1200 'A:cp and A:eqiad' 'varnish-frontend-restart': T253093

Maintenance_bot removed a project: Patch-For-Review.May 12 2023, 1:30 PM
ssingh closed this task as Resolved.May 12 2023, 5:31 PM

We have bumped the size of the shared memory log and rolled out the changes to all sites by restarting varnish-frontend. Marking this as closed.

gerritbot added a comment.Sep 19 2023, 12:25 PM

Change 958923 had a related patch set uploaded (by BBlack; author: BBlack):

[operations/puppet@production] varnish: unify vsl_size to new default

https://gerrit.wikimedia.org/r/958923

gerritbot added a project: Patch-For-Review.Sep 19 2023, 12:25 PM
gerritbot added a comment.Sep 19 2023, 12:45 PM

Change 958923 merged by BBlack:

[operations/puppet@production] varnish: unify vsl_size to new default

https://gerrit.wikimedia.org/r/958923

Maintenance_bot removed a project: Patch-For-Review.Sep 19 2023, 1:11 PM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL