createrepo_c errors are swallowed by copr-repo wrapper?

[praiskup]

[2024-02-29 21:36:02,316][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][copr-backend-process-action:handle_action:24] Handling action 1511660
[2024-02-29 21:36:02,372][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][copr-backend-process-action:handle_action:34] Executing: <Createrepo(Action): {'action_type': 3, 'copr_id': 58642, 'created_on': 1709242549, 'data': '{"ownername": "sergiomb", "projectname": "electrons", "project_dirnames": ["electrons"], "chroots": ["fedora-rawhide-x86_64", "fedora-rawhide-aarch64", "fedora-39-x86_64", "fedora-38-x86_64", "fedora-38-aarch64", "fedora-39-aarch64", "fedora-40-x86_64", "fedora-40-aarch64"], "appstream": false, "devel": false}', 'ended_on': None, 'id': 1511660, 'message': None, 'new_value': None, 'object_id': 0, 'object_type': 'repository', 'old_value': None, 'priority': 0, 'result': 0}>
[2024-02-29 21:36:02,373][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][actions.py:run:113] Action createrepo
[2024-02-29 21:36:02,374][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][actions.py:run:127] Creating repo for: sergiomb/electrons/fedora-rawhide-x86_64
[2024-02-29 21:36:02,376][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Running command 'copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-rawhide-x86_64 --no-appstream-metadata' as PID 2382843
[2024-02-29 21:36:03,326][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Finished after 0 seconds with exit code 1 (copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-rawhide-x86_64 --no-appstream-metadata)
[2024-02-29 21:36:03,326][ ERROR][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:call_copr_repo:684] Createrepo failed
[2024-02-29 21:36:03,327][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][actions.py:run:127] Creating repo for: sergiomb/electrons/fedora-rawhide-aarch64
[2024-02-29 21:36:03,328][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Running command 'copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-rawhide-aarch64 --no-appstream-metadata' as PID 2382948
[2024-02-29 21:36:04,305][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Finished after 0 seconds with exit code 1 (copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-rawhide-aarch64 --no-appstream-metadata)
[2024-02-29 21:36:04,307][ ERROR][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:call_copr_repo:684] Createrepo failed
[2024-02-29 21:36:04,308][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][actions.py:run:127] Creating repo for: sergiomb/electrons/fedora-39-x86_64
[2024-02-29 21:36:04,311][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Running command 'copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-39-x86_64 --no-appstream-metadata' as PID 2383075
[2024-02-29 21:36:05,357][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Finished after 1 seconds with exit code 0 (copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-39-x86_64 --no-appstream-metadata)
[2024-02-29 21:36:05,358][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][actions.py:run:127] Creating repo for: sergiomb/electrons/fedora-38-x86_64
[2024-02-29 21:36:05,360][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Running command 'copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-38-x86_64 --no-appstream-metadata' as PID 2383218
[2024-02-29 21:36:06,474][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Finished after 1 seconds with exit code 0 (copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-38-x86_64 --no-appstream-metadata)
[2024-02-29 21:36:06,475][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][actions.py:run:127] Creating repo for: sergiomb/electrons/fedora-38-aarch64
[2024-02-29 21:36:06,477][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Running command 'copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-38-aarch64 --no-appstream-metadata' as PID 2383317
[2024-02-29 21:36:07,600][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Finished after 1 seconds with exit code 0 (copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-38-aarch64 --no-appstream-metadata)
[2024-02-29 21:36:07,603][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][actions.py:run:127] Creating repo for: sergiomb/electrons/fedora-39-aarch64
[2024-02-29 21:36:07,605][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Running command 'copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-39-aarch64 --no-appstream-metadata' as PID 2383423
[2024-02-29 21:36:08,661][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Finished after 1 seconds with exit code 0 (copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-39-aarch64 --no-appstream-metadata)
[2024-02-29 21:36:08,662][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][actions.py:run:127] Creating repo for: sergiomb/electrons/fedora-40-x86_64
[2024-02-29 21:36:08,663][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Running command 'copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-40-x86_64 --no-appstream-metadata' as PID 2383609
[2024-02-29 21:36:09,578][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Finished after 0 seconds with exit code 1 (copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-40-x86_64 --no-appstream-metadata)
[2024-02-29 21:36:09,579][ ERROR][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:call_copr_repo:684] Createrepo failed
[2024-02-29 21:36:09,580][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][actions.py:run:127] Creating repo for: sergiomb/electrons/fedora-40-aarch64
[2024-02-29 21:36:09,581][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Running command 'copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-40-aarch64 --no-appstream-metadata' as PID 2383715
[2024-02-29 21:36:10,442][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:_info:109] Finished after 0 seconds with exit code 1 (copr-repo --batched /var/lib/copr/public_html/results/sergiomb/electrons/fedora-40-aarch64 --no-appstream-metadata)
[2024-02-29 21:36:10,442][ ERROR][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][helpers.py:call_copr_repo:684] Createrepo failed
[2024-02-29 21:36:10,444][  INFO][PID:2382804][/usr/bin/copr-backend-process-action.managed.pid-2382804][copr-backend-process-action:handle_task:46] Action 1511660 ended with status=FAILURE

The error is available in modifyrepo.log:

[2024-02-29 21:36:09,448][  INFO][PID:2383609][/usr/bin/copr-repo.pid-2383609][helpers.py:_info:109] Finished after 0 seconds with exit code 2 (/usr/bin/createrepo_c /var/lib/copr/public_html/results/sergiomb/electrons/fedora-40-x86_64 stdout:
Directory walk started
Directory walk done - 30 packages
Loaded information about 26 packages
Temporary output repo path: /var/lib/copr/public_html/results/sergiomb/electrons/fedora-40-x86_64/.repodata/
Pool started (with 8 workers)
Pool finished with errors
Warning: There were some invalid packages: we have to recompress other, filelists and primary xml metadata files in order to have correct package counts
New and old repodata match, not updating.

stderr:
C_CREATEREPOLIB: Critical: Cannot dump XML for nodejs-electron (9584d3fed1bde5062f19bbedb20081cbe96dc7f10f92e0c22821d9a1e2969af0): Forbidden control chars found (ASCII values <32 except 9, 10 and 13).
C_CREATEREPOLIB: Critical: Cannot dump XML for nodejs-electron (6cf2159a44f86310c430292ceaa231a71f07eda8590f2507ab884771d0f5ade8): Forbidden control chars found (ASCII values <32 except 9, 10 and 13).
C_CREATEREPOLIB: Critical: Cannot dump XML for nodejs-electron-devel (b5373d44fd0b922cf7b43bb27ad39b9c0878ce44edb12959b9915b1849a8e0f3): Forbidden control chars found (ASCII values <32 except 9, 10 and 13).
C_CREATEREPOLIB: Critical: Cannot dump XML for nodejs-electron-doc (6551f31fd59ced0f6832fefce64a94deb9230dae3b74a871311e1b1d71a4a635): Forbidden control chars found (ASCII values <32 except 9, 10 and 13).
Warning: Package 'element-desktop-0:1.11.58-2.fc40.src' has duplicate metadata entries, only one should exist
Warning:     Sourced from location: '07032563-element-desktop/element-desktop-1.11.58-2.fc40.src.rpm', build timestamp: 1708306300
Warning:     Sourced from location: '07032866-element-desktop/element-desktop-1.11.58-2.fc40.src.rpm', build timestamp: 1708311752
Warning: Package 'element-desktop-0:1.11.58-3.fc40.src' has duplicate metadata entries, only one should exist 
Warning:     Sourced from location: '07046217-element-desktop/element-desktop-1.11.58-3.fc40.src.rpm', build timestamp: 1708532509
Warning:     Sourced from location: '07089283-element-desktop/element-desktop-1.11.58-3.fc40.src.rpm', build timestamp: 1709159010
Warning:     Sourced from location: '07089348-element-desktop/element-desktop-1.11.58-3.fc40.src.rpm', build timestamp: 1709160815
Warning:     Sourced from location: '07089418-element-desktop/element-desktop-1.11.58-3.fc40.src.rpm', build timestamp: 1709165649

But such errors do not bubble up into the backend.log, etc.

[praiskup]

Data backed-up here: https://download.copr.fedorainfracloud.org/archive/issues/copr-3163/

[sergiomb2]

rpm-software-management/createrepo_c#165 , since this merge we got these problems , I will try debug createrepo_c to give write where is the problem

[praiskup]

rpm-software-management/createrepo_c#327