Numerous git-checkout loadings are failing in production while they should not

added Git loader activity::MRO priority:Normal labels

Could you check with the docker image container-registry.softwareheritage.org/swh/infra/swh-apps/loader_git:20240126.1?

Loading of an origin that failed is also successful when running locally in the docker image used in production:

$ docker run -it --entrypoint /bin/bash container-registry.softwareheritage.org/swh/infra/swh-apps/loader_git:20240126.1
swh@35510ca2c995:~$ swh -l DEBUG loader run git-checkout https://github.com/tdf/libcmis ref=v0.6.0 checksum_layout=nar checksums='{"sha256": "136038b8951acaa30cc5589fcde01e60a2cbf85895daf4a134d7577b964b5d9e"}'
DEBUG:swh.loader.cli:ctx: <click.core.Context object at 0x7ff3104361d0>
ERROR:root:Config file /etc/swh/config.yml does not exist, ignoring it.
DEBUG:swh.loader.cli:config_file: /etc/swh/config.yml
DEBUG:swh.loader.cli:config: {}
WARNING:swh.loader.cli:No storage configuration detected, using an in-memory storage instead.
DEBUG:swh.loader.cli:kw: {'ref': 'v0.6.0', 'checksum_layout': 'nar', 'checksums': {'sha256': '136038b8951acaa30cc5589fcde01e60a2cbf85895daf4a134d7577b964b5d9e'}}
DEBUG:swh.loader.cli:registry: {'task_modules': [], 'loader': <class 'swh.loader.git.directory.GitCheckoutLoader'>}
DEBUG:swh.loader.cli:loader class: <class 'swh.loader.git.directory.GitCheckoutLoader'>
DEBUG:swh.loader.git.directory.GitCheckoutLoader:Loader checksums computation: nar
INFO:swh.loader.git.directory.GitCheckoutLoader:Load origin 'https://github.com/tdf/libcmis' with type 'git-checkout'
DEBUG:swh.loader.git.directory.GitCheckoutLoader:lister_not provided, skipping extrinsic origin metadata
DEBUG:swh.core.statsd:Error submitting statsd packet. Dropping the packet and closing the socket.
DEBUG:swh.loader.git.directory.GitCheckoutLoader:Artifact <git-checkout> with path /tmp/tmps5xtmfe5/libcmis
DEBUG:swh.loader.git.directory.GitCheckoutLoader:Artifact <git-checkout> to check nar hashes: /tmp/tmps5xtmfe5/libcmis
DEBUG:swh.loader.git.directory.GitCheckoutLoader:Number of skipped contents: 0
DEBUG:swh.loader.git.directory.GitCheckoutLoader:Number of contents: 333
DEBUG:swh.loader.git.directory.GitCheckoutLoader:Number of directories: 21
DEBUG:swh.core.statsd:Error submitting statsd packet. Dropping the packet and closing the socket.
DEBUG:swh.core.statsd:Error submitting statsd packet. Dropping the packet and closing the socket.
DEBUG:swh.core.statsd:Error submitting statsd packet. Dropping the packet and closing the socket.
DEBUG:swh.loader.git.directory.GitCheckoutLoader:cleanup
{'status': 'eventful'} for origin 'https://github.com/tdf/libcmis'

How about loading several origins one after the other? is the /tmp-dir properly cleaned up?

How about loading several origins one after the other?

I scheduled the origins to load in the docker environment using that script create-git-checkout-loading-tasks and so far the only hash mismatch errors I got are real ones (they are still a couple left, for instance if upstream force pushed a tag), other origins are loading fine.

is the /tmp-dir properly cleaned up?

It is as a context manager is used.

fwiw, a run on a (staging) stale loader-git-checkout pod gave the following [1]

(Besides failing, it seems to have ignored the log as DEBUG directive too).

[1]

swh@loader-git-checkout-584c7b964f-zjfgl:~$ grep dulwich requirements-frozen.txt
dulwich==0.21.7
swh@loader-git-checkout-584c7b964f-zjfgl:~$ git --version
git version 2.30.2
swh@loader-git-checkout-584c7b964f-zjfgl:~$ swh -l DEBUG loader run git-checkout https://github.com/tdf/libcmis \
                                     ref=v0.6.0 \
                                     checksum_layout=nar \
                                     checksums='{"sha256": "136038b8951acaa30cc5589fcde01e60a2cbf85895daf4a134d7577b964b5d9e"}'
{"asctime": "2024-01-30 13:50:28,853", "threadName": "MainThread", "pathname": "/opt/swh/.local/lib/python3.10/site-packages/swh/loader/core/loader.py", "lineno": 414, "funcName": "load", "task_name": null, "task_id": null, "name": "swh.loader.git.directory.GitCheckoutLoader", "levelname": "INFO", "message": "Load origin 'https://github.com/tdf/libcmis' with type 'git-checkout'"}
{"asctime": "2024-01-30 13:50:29,817", "threadName": "MainThread", "pathname": "/opt/swh/.local/lib/python3.10/site-packages/swh/loader/core/loader.py", "lineno": 513, "funcName": "load", "task_name": null, "task_id": null, "name": "swh.loader.git.directory.GitCheckoutLoader", "levelname": "ERROR", "message": "Loading failure, updating to `failed` status", "exc_info": "Traceback (most recent call last):\n  File \"/opt/swh/.local/lib/python3.10/site-packages/swh/loader/core/loader.py\", line 451, in load\n    more_data_to_fetch = self.fetch_data()\n  File \"/opt/swh/.local/lib/python3.10/site-packages/swh/loader/core/loader.py\", line 837, in fetch_data\n    raise errors[0]\nValueError: Checksum mismatched on <https://github.com/tdf/libcmis>: {'sha256': '512b6149a8e249ffedea1977f3239ce55247b0e66e97f7566f37b4df9c4a26f1'} != {'sha256': '136038b8951acaa30cc5589fcde01e60a2cbf85895daf4a134d7577b964b5d9e'}", "swh_task_args": [], "swh_task_kwargs": {"origin": "https://github.com/tdf/libcmis", "lister_name": null, "lister_instance_name": null}}
{'status': 'failed'} for origin 'https://github.com/tdf/libcmis'
swh@loader-git-checkout-584c7b964f-zjfgl:~$ ls /tmp/
pymp-n3iqrsrm
swh@loader-git-checkout-584c7b964f-zjfgl:~$ ls /tmp/*

That kind of issue is also experienced on visit type tarball-directory.

For instance the origin https://gitlab.com/api/v4/projects/iucode-tool%2Fiucode-tool/repository/archive.tar.gz?sha=v2.3.1 failed to be loaded (see sentry report) while it is fine when running locally:

$ swh -l DEBUG loader run directory https://gitlab.com/api/v4/projects/iucode-tool%2Fiucode-tool/repository/archive.tar.gz?sha=v2.3.1 fallback_urls='[]' checksum_layout='nar' checksums='{"sha256": "6a30e9cb08327ab6ef81eae7d1bf13e232545a2b0ccf0ae1c0a3b583b88eb411"}'
WARNING:swh.loader.cli:No storage configuration detected, using an in-memory storage instead.
DEBUG:swh.loader.cli:kw: {'fallback_urls': [], 'checksum_layout': 'nar', 'checksums': {'sha256': '6a30e9cb08327ab6ef81eae7d1bf13e232545a2b0ccf0ae1c0a3b583b88eb411'}}
DEBUG:swh.loader.cli:registry: {'task_modules': ['swh.loader.core.tasks'], 'loader': <class 'swh.loader.core.loader.TarballDirectoryLoader'>}
DEBUG:swh.loader.cli:loader class: <class 'swh.loader.core.loader.TarballDirectoryLoader'>
DEBUG:swh.loader.core.loader.TarballDirectoryLoader:Loader checksums computation: nar
INFO:swh.loader.core.loader.TarballDirectoryLoader:Load origin 'https://gitlab.com/api/v4/projects/iucode-tool%2Fiucode-tool/repository/archive.tar.gz?sha=v2.3.1' with type 'tarball-directory'
DEBUG:swh.loader.core.loader.TarballDirectoryLoader:lister_not provided, skipping extrinsic origin metadata
DEBUG:swh.core.statsd:Error submitting statsd packet. Dropping the packet and closing the socket.
DEBUG:swh.loader.core.loader.TarballDirectoryLoader:prepare; origin_url=https://gitlab.com/api/v4/projects/iucode-tool%2Fiucode-tool/repository/archive.tar.gz?sha=v2.3.1 fallback=https://gitlab.com/api/v4/projects/iucode-tool%2Fiucode-tool/repository/archive.tar.gz?sha=v2.3.1 scheme=https path=/api/v4/projects/iucode-tool%2Fiucode-tool/repository/archive.tar.gz
DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): gitlab.com:443
DEBUG:urllib3.connectionpool:https://gitlab.com:443 "GET /api/v4/projects/iucode-tool%2Fiucode-tool/repository/archive.tar.gz?sha=v2.3.1 HTTP/1.1" 200 None
DEBUG:swh.loader.package.utils:filename: iucode-tool-v2.3.1-9ab8dcb833945ffa71d8bfc034b27ef7d858b3dc.tar.gz
DEBUG:swh.loader.package.utils:filepath: /tmp/tmpmmobvxl2/iucode-tool-v2.3.1-9ab8dcb833945ffa71d8bfc034b27ef7d858b3dc.tar.gz
DEBUG:swh.loader.package.utils:extrinsic_metadata: {'length': 79521, 'filename': 'iucode-tool-v2.3.1-9ab8dcb833945ffa71d8bfc034b27ef7d858b3dc.tar.gz', 'checksums': {'sha1': '5af5f6dec536434503e604e0c8beca388af1698b', 'sha256': '76e79fe4eaee75cfb97d651ec009b557079ba330abfedae06c034f8901dcbe44'}, 'url': 'https://gitlab.com/api/v4/projects/iucode-tool%2Fiucode-tool/repository/archive.tar.gz?sha=v2.3.1'}
DEBUG:swh.loader.core.loader.TarballDirectoryLoader:uncompressed path to directory: /tmp/tmpmmobvxl2/src
DEBUG:swh.loader.core.loader.TarballDirectoryLoader:Artifact <tarball-directory> with path /tmp/tmpmmobvxl2/src/iucode-tool-v2.3.1-9ab8dcb833945ffa71d8bfc034b27ef7d858b3dc
DEBUG:swh.loader.core.loader.TarballDirectoryLoader:Artifact <tarball-directory> to check nar hashes: /tmp/tmpmmobvxl2/src/iucode-tool-v2.3.1-9ab8dcb833945ffa71d8bfc034b27ef7d858b3dc
DEBUG:swh.loader.core.loader.TarballDirectoryLoader:Number of skipped contents: 0
DEBUG:swh.loader.core.loader.TarballDirectoryLoader:Number of contents: 22
DEBUG:swh.loader.core.loader.TarballDirectoryLoader:Number of directories: 2
DEBUG:swh.loader.core.loader.TarballDirectoryLoader:cleanup
{'status': 'eventful'} for origin 'https://gitlab.com/api/v4/projects/iucode-tool%2Fiucode-tool/repository/archive.tar.gz?sha=v2.3.1'

This issue is hard to debug without inspecting the content of the directory where the NAR hash computation failed.

I think it could make sense, in case of such failure, to dump the output of the repository listing along the SWHIDs for contents and directories in a file and attach it to the sentry event.

It would make sense to add an explicit flag to the loader, to dump the temporary directory, which we could inject in the listed origin entry (or just schedule manually). Sentry isn't really set up to support (potentially large) attachments for all failing visit events.

(even with the built-in 20MB limit, that could add up pretty quick, I think)

It would make sense to add an explicit flag to the loader, to dump the temporary directory

Do you mean creating a compressed tarball for it and dumping it to /tmp ?

Ah, I re-read what you wrote (attaching a text file with a recursive directory + swhid listing) and it makes more sense, sorry !

I guess sending that to sentry unconditionally would not be a problem.

I need to make some tests but I think after gzip compression, the size of the sentry attachment file should have a reasonable size in most of cases.

yeah, indeed

fwiw, I ended up with swh/devel/swh-loader-core!513 (closed) (tests are failing due to the incompatibility between pytest 8.0 and pytest-posgresql < 4)

mentioned in commit anlambert/swh-loader-core@f00c727a

mentioned in merge request swh/devel/swh-loader-core!513 (closed)

@vsellier, you were right about the possible cause of that issue in our f2F discussion today !

I gave another look to our NAR hash computation code and indeed file permissions are used during that processing. In particular execution permission is checked and influences the hash output value.

So I took the following failure example for the git-checkout visit of repository https://gitlab.com/mdds/mdds at tag 2.1.1 in the hope to reproduce the same invalid NAR hash reported in the sentry event (first one below).

Checksum mismatched on <https://gitlab.com/mdds/mdds>: 
{'sha256':'b30561047d7a3d212699f8fd2bc7a675d7780cef540022a27185b6220f370d16'} != 
{'sha256': '6b8d762e980389833c4cc4e8694ad3947b5b9584b51de873ac33b0bc8000c620'}

First I checked that we could compute the correct NAR hash without hacking on our NAR hashing code:

$ git checkout https://gitlab.com/mdds/mdds
Cloning into 'mdds'...
warning: redirecting to https://gitlab.com/mdds/mdds.git/
remote: Enumerating objects: 20109, done.
remote: Counting objects: 100% (581/581), done.
remote: Compressing objects: 100% (194/194), done.
remote: Total 20109 (delta 385), reused 581 (delta 385), pack-reused 19528
Receiving objects: 100% (20109/20109), 6.70 MiB | 20.79 MiB/s, done.
Resolving deltas: 100% (13601/13601), done.

$ cd mdds

$ git checkout 2.1.1
HEAD is now at d0a5a816 Fix make distcheck

$ swh nar -x .
6b8d762e980389833c4cc4e8694ad3947b5b9584b51de873ac33b0bc8000c620

All good ! Then I commented out the code checking file execution permission in our NAR hashing code linked above and computed the hash again.

$ swh nar -x .
b30561047d7a3d212699f8fd2bc7a675d7780cef540022a27185b6220f370d16

\o/ We obtained the same invalid NAR hash !

So the cause of the issue is that executable files cannot be detected as such in our production environment likely due to the use of noexec option when mounting /tmp.

So, I mentioned it on IRC, and indeed os.access(..., os.X_OK) honors the noexec flag. It also wouldn't match a file that has an executable bit that the effective gid can't honor, which might happen if we ever started fully separating the decompression process from the loading process.

So, we should instead use os.lstat(...).st_mode & 0o111 != 0, which only relies on whether the filesystem bits are set to executable, and doesn't check the permissions of the mountpoint or the owner of the file.

@zimoun jsyk ^ ;p

mentioned in commit ardumont/swh-loader-core@7a8397d2

mentioned in merge request swh/devel/swh-loader-core!514 (merged)

mentioned in issue #5222 (closed)

mentioned in commit ardumont/swh-loader-core@7884330d

mentioned in issue #5233 (closed)

mentioned in commit swh/infra/ci-cd/swh-charts@fd3381b1

The deployment got done and the sentry issue marked as solved yesterday. So far, the issue did not get raised back (as regression) by the loaders yet.

I've rescheduled in staging the failed git-checkout tasks [2] (which are the dominant occurrences here) [1] as another check. I've bumped the number of pods to ingest those to 3 so it's getting a bit faster...

If all is good, i'll do the same on production after that.

[1]

swh@swh-toolbox-d96bc8d9b-sxdzg:~$ swh scheduler -C $SWH_CONFIG_FILENAME origin send-to-celery git-checkout --lister-name nixguix --lister-instance-name guix.gnu.org --failed-cooldown '1 second'
10000 slots available in celery queue
4223 visits to send to celery

[2]

Forge guix.gnu.org (nixguix) has 33368 scheduled ingests in the scheduler.
failed       : 4640
None         : 5402
not_found    : 56
successful   : 23270
total        : 33368
success rate : 69.73747302805083%

The issue got marked as regression but I gather that's because some hash mismatch can still happen (if the issue is upstream of guix's as it already happened before).

Anyway, the numbers are going up fast for git-checkout origins [1]

3782 or so at the previous timestamp to 4123 now.

[1] https://webapp.staging.swh.network/coverage

As a datapoint on the progress [1]

swh@swh-toolbox-d96bc8d9b-sxdzg:~$ swh scheduler -C $SWH_CONFIG_FILENAME origin check-ingested-origins nixguix guix.gnu.org
Forge guix.gnu.org (nixguix) has 33368 scheduled ingests in the scheduler.
failed       : 4380
None         : 5399
not_found    : 56
successful   : 23533
total        : 33368
success rate : 70.52565332054664%

mentioned in commit swh/infra/ci-cd/swh-charts@44698510

mentioned in commit swh/infra/ci-cd/swh-charts@c4c8f6fc

98.4% of success, I consider this issue ok.

fwiw, I've rescheduled other origin types (e.g. hg-checkout, git, ...), ingestion is ongoing. But this has nothing to do with this issue.

Forge guix.gnu.org (nixguix) has 29571 scheduled ingests in the scheduler.
failed       : 382
None         : 41
not_found    : 49
successful   : 29099
total        : 29571
success rate : 98.40384160156911%

closed

mentioned in commit ardumont/swh-scheduler@d9dcef4c

mentioned in commit ardumont/swh-scheduler@863d931f

mentioned in commit ardumont/swh-scheduler@fe72a50c

mentioned in merge request swh/devel/swh-scheduler!367 (merged)

Numerous git-checkout loadings are failing in production while they should not

Designs

Child items ...

Activity