Train presync timer in unhealthy state
Closed, ResolvedPublic
Actions

Assigned To

Authored By

	jnuche
	Apr 2 2024, 11:57 AM

Project Tags

Referenced Files

None

Subscribers

Aklapper

jnuche

taavi

Description

Presync started running as scheduled at 3:00 UTC on 2024-04-02 and then failed due to a transient CI error: https://gerrit.wikimedia.org/r/c/operations/mediawiki-config/+/1016069

The process, however, doesn't seem to have completed one way or another. No email with the result arrived at the mailing list. The systemd unit shows as "active" but its next trigger shows as "not available":

[jnuche@deploy1002 ~]$ systemctl status train-presync.timer
● train-presync.timer - Periodic execution of train-presync.service
   Loaded: loaded (/lib/systemd/system/train-presync.timer; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2024-03-21 12:12:52 UTC; 1 weeks 4 days ago
  Trigger: n/a

[jnuche@deploy1002 ~]$ systemctl list-timers --all | grep -e "NEXT\|train"
NEXT                         LEFT          LAST                         PASSED       UNIT                                                ACTIVATES
n/a                          n/a           Tue 2024-04-02 03:00:03 UTC  8h ago       train-presync.timer                                 train-presync.service

There are no recent changes to the timer's puppet config. I think we could us help from someone from ops to take a look at this.

Related Objects

Mentioned In: T361585: scap deploy-promote needs a timeout when waiting for CI
Mentioned Here: T361585: scap deploy-promote needs a timeout when waiting for CI

Event Timeline

jnuche created this task.Apr 2 2024, 11:57 AM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptApr 2 2024, 11:57 AM

The train-presync.service service unit is still shown as running:

taavi@deploy1002 ~ $ systemctl status train-presync.service 
● train-presync.service - Perform beginning-of-week train operations
   Loaded: loaded (/lib/systemd/system/train-presync.service; static; vendor preset: enabled)
   Active: activating (start) since Tue 2024-04-02 03:00:03 UTC; 9h ago
     Docs: https://wikitech.wikimedia.org/wiki/Monitoring/systemd_unit_state
 Main PID: 24118 (systemd-timer-m)
    Tasks: 3 (limit: 4915)
   Memory: 675.2M
   CGroup: /system.slice/train-presync.service
           ├─ 3983 /var/lib/scap/scap/bin/python3 /usr/bin/scap deploy-promote --yes testwikis 1.42.0-wmf.25 -D full_image_buil
           ├─24118 /usr/bin/python3 /usr/local/bin/systemd-timer-mail-wrapper --subject train-presync --mail-to releng@lists.wi
           └─24170 /var/lib/scap/scap/bin/python3 /usr/bin/scap stage-train -Dfull_image_build:True --yes auto

It's trying to... something with Git:

Apr 02 12:02:17 deploy1002 scap[3983]: @cee: {"@version": 1, "type": "scap", "host": "deploy1002", "script": "/usr/bin/scap", "user": "mwpresync", "levelname": "DEBUG", "pathname": "/var/lib/scap/scap/lib/python3.7/site-packages/scap/runcmd.py", "filename": "runcmd.py", "module": "runcmd", "stack_info": null, "lineno": 66, "funcName": "_runcmd", "process": 3983, "channel": "root", "@timestamp": "2024-04-02T12:02:17Z", "message": "Running ['git', 'fetch'] with {'stdout': -1, 'stderr': -1, 'text': True, 'stdin': -3}"}
Apr 02 12:02:18 deploy1002 scap[3983]: @cee: {"@version": 1, "type": "scap", "host": "deploy1002", "script": "/usr/bin/scap", "user": "mwpresync", "levelname": "DEBUG", "pathname": "/var/lib/scap/scap/lib/python3.7/site-packages/scap/runcmd.py", "filename": "runcmd.py", "module": "runcmd", "stack_info": null, "lineno": 66, "funcName": "_runcmd", "process": 3983, "channel": "root", "@timestamp": "2024-04-02T12:02:18Z", "message": "Running ['git', 'log', 'HEAD..FETCH_HEAD'] with {'stdout': -1, 'stderr': -1, 'text': True, 'stdin': -3}"}
Apr 02 12:02:23 deploy1002 scap[3983]: @cee: {"@version": 1, "type": "scap", "host": "deploy1002", "script": "/usr/bin/scap", "user": "mwpresync", "levelname": "DEBUG", "pathname": "/var/lib/scap/scap/lib/python3.7/site-packages/scap/runcmd.py", "filename": "runcmd.py", "module": "runcmd", "stack_info": null, "lineno": 66, "funcName": "_runcmd", "process": 3983, "channel": "root", "@timestamp": "2024-04-02T12:02:23Z", "message": "Running ['git', 'fetch'] with {'stdout': -1, 'stderr': -1, 'text': True, 'stdin': -3}"}
Apr 02 12:02:23 deploy1002 scap[3983]: @cee: {"@version": 1, "type": "scap", "host": "deploy1002", "script": "/usr/bin/scap", "user": "mwpresync", "levelname": "DEBUG", "pathname": "/var/lib/scap/scap/lib/python3.7/site-packages/scap/runcmd.py", "filename": "runcmd.py", "module": "runcmd", "stack_info": null, "lineno": 66, "funcName": "_runcmd", "process": 3983, "channel": "root", "@timestamp": "2024-04-02T12:02:23Z", "message": "Running ['git', 'log', 'HEAD..FETCH_HEAD'] with {'stdout': -1, 'stderr': -1, 'text': True, 'stdin': -3}"}
Apr 02 12:02:28 deploy1002 scap[3983]: @cee: {"@version": 1, "type": "scap", "host": "deploy1002", "script": "/usr/bin/scap", "user": "mwpresync", "levelname": "DEBUG", "pathname": "/var/lib/scap/scap/lib/python3.7/site-packages/scap/runcmd.py", "filename": "runcmd.py", "module": "runcmd", "stack_info": null, "lineno": 66, "funcName": "_runcmd", "process": 3983, "channel": "root", "@timestamp": "2024-04-02T12:02:28Z", "message": "Running ['git', 'fetch'] with {'stdout': -1, 'stderr': -1, 'text': True, 'stdin': -3}"}
Apr 02 12:02:28 deploy1002 scap[3983]: @cee: {"@version": 1, "type": "scap", "host": "deploy1002", "script": "/usr/bin/scap", "user": "mwpresync", "levelname": "DEBUG", "pathname": "/var/lib/scap/scap/lib/python3.7/site-packages/scap/runcmd.py", "filename": "runcmd.py", "module": "runcmd", "stack_info": null, "lineno": 66, "funcName": "_runcmd", "process": 3983, "channel": "root", "@timestamp": "2024-04-02T12:02:28Z", "message": "Running ['git', 'log', 'HEAD..FETCH_HEAD'] with {'stdout': -1, 'stderr': -1, 'text': True, 'stdin': -3}"}
Apr 02 12:02:33 deploy1002 scap[3983]: @cee: {"@version": 1, "type": "scap", "host": "deploy1002", "script": "/usr/bin/scap", "user": "mwpresync", "levelname": "DEBUG", "pathname": "/var/lib/scap/scap/lib/python3.7/site-packages/scap/runcmd.py", "filename": "runcmd.py", "module": "runcmd", "stack_info": null, "lineno": 66, "funcName": "_runcmd", "process": 3983, "channel": "root", "@timestamp": "2024-04-02T12:02:33Z", "message": "Running ['git', 'fetch'] with {'stdout': -1, 'stderr': -1, 'text': True, 'stdin': -3}"}
Apr 02 12:02:33 deploy1002 scap[3983]: @cee: {"@version": 1, "type": "scap", "host": "deploy1002", "script": "/usr/bin/scap", "user": "mwpresync", "levelname": "DEBUG", "pathname": "/var/lib/scap/scap/lib/python3.7/site-packages/scap/runcmd.py", "filename": "runcmd.py", "module": "runcmd", "stack_info": null, "lineno": 66, "funcName": "_runcmd", "process": 3983, "channel": "root", "@timestamp": "2024-04-02T12:02:33Z", "message": "Running ['git', 'log', 'HEAD..FETCH_HEAD'] with {'stdout': -1, 'stderr': -1, 'text': True, 'stdin': -3}"}

And that something is apparently https://gerrit.wikimedia.org/r/c/operations/mediawiki-config/+/1016069 which failed to merge due to a jenkins rsync error?

Thanks for taking a look @taavi! Can you also kill the service?

I can see where the problem started in the OpenSearch logs: https://logstash.wikimedia.org/goto/38d2980b876831a11df40230fb1f703d and that's led me to the scap module where the bug is. I'm going to file separate task for it.

Mentioned in SAL (#wikimedia-operations) [2024-04-02T12:28:08Z] <taavi> taavi@deploy1002 ~ $ sudo systemctl kill train-presync.service # T361580

Yes. Done.

@taavi kiitos :)

Closing this in favor of T361585

Train presync timer in unhealthy stateClosed, ResolvedPublicActions

Description

Related Objects

Event Timeline

Train presync timer in unhealthy state
Closed, ResolvedPublic
Actions