#11763 Lot of errors after `git push`
Closed: Fixed with Explanation a year ago by zlopez. Opened a year ago by vondruch.

This is my repo:

$ git remote -v
fork    ssh://vondruch@pkgs.fedoraproject.org/forks/vondruch/rpms/ruby.git (fetch)
fork    ssh://vondruch@pkgs.fedoraproject.org/forks/vondruch/rpms/ruby.git (push)
origin  ssh://vondruch@pkgs.fedoraproject.org/rpms/ruby (fetch)
origin  ssh://vondruch@pkgs.fedoraproject.org/rpms/ruby (push)

And there was a lot of noise after pushing some changes:

$ git push fork HEAD
Enumerating objects: 17, done.
Counting objects: 100% (17/17), done.
Delta compression using up to 8 threads
Compressing objects: 100% (15/15), done.
Writing objects: 100% (15/15), 1.86 KiB | 951.00 KiB/s, done.
Total 15 (delta 10), reused 0 (delta 0), pack-reused 0
remote: --- Logging error ---
remote: Traceback (most recent call last):
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 72, in emit
remote:     self.doRollover()
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 402, in doRollover
remote:     self.rotate(self.baseFilename, dfn)
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 113, in rotate
remote:     os.rename(source, dest)
remote: PermissionError: [Errno 13] Permission denied: '/var/log/pagure/pagure_auth.log' -> '/var/log/pagure/pagure_auth.log.2024-02-07'
remote: Call stack:
remote:   File "hooks/pre-receive", line 48, in <module>
remote:     run_hook_file(hooktype)
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/__init__.py", line 550, in run_hook_file
remote:     pull_request,
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/__init__.py", line 323, in run_project_hooks
remote:     authbackend = get_git_auth_helper()
remote:   File "/usr/lib/python3.6/site-packages/pagure/lib/git_auth.py", line 66, in get_git_auth_helper
remote:     _log.info("Looking for backend: %s", backend)
remote: Message: 'Looking for backend: %s'
remote: Arguments: ('distgit',)
remote: --- Logging error ---
remote: Traceback (most recent call last):
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 72, in emit
remote:     self.doRollover()
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 402, in doRollover
remote:     self.rotate(self.baseFilename, dfn)
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 113, in rotate
remote:     os.rename(source, dest)
remote: PermissionError: [Errno 13] Permission denied: '/var/log/pagure/pagure_auth.log' -> '/var/log/pagure/pagure_auth.log.2024-02-07'
remote: Call stack:
remote:   File "hooks/pre-receive", line 48, in <module>
remote:     run_hook_file(hooktype)
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/__init__.py", line 550, in run_hook_file
remote:     pull_request,
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/__init__.py", line 353, in run_project_hooks
remote:     repodir=repodir,
remote:   File "/usr/lib/python3.6/site-packages/dist_git_auth.py", line 197, in check_acl
remote:     self.debug("Protected namespaces: %s" % self.protected_namespaces)
remote:   File "/usr/lib/python3.6/site-packages/dist_git_auth.py", line 128, in debug
remote:     _log.debug(msg)
remote: Message: "Protected namespaces: ['rpms', 'modules', 'container']"
remote: Arguments: ()

... snip ...

remote: --- Logging error ---
remote: Traceback (most recent call last):
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 72, in emit
remote:     self.doRollover()
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 402, in doRollover
remote:     self.rotate(self.baseFilename, dfn)
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 113, in rotate
remote:     os.rename(source, dest)
remote: PermissionError: [Errno 13] Permission denied: '/var/log/pagure/pagure_auth.log' -> '/var/log/pagure/pagure_auth.log.2024-02-07'
remote: Call stack:
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/files/post-receive", line 48, in <module>
remote:     run_hook_file(hooktype)
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/__init__.py", line 550, in run_hook_file
remote:     pull_request,
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/__init__.py", line 392, in run_project_hooks
remote:     changes=changes,
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/__init__.py", line 111, in runhook
remote:     changes=changes,
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/default.py", line 445, in post_receive
remote:     oldrev,
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/default.py", line 222, in send_notifications
remote:     send_fedmsg_notifications(project, topic, msg)
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/default.py", line 69, in send_fedmsg_notifications
remote:     pagure.lib.notify.fedora_messaging_publish(topic, msg)
remote:   File "/usr/lib/python3.6/site-packages/pagure/lib/notify.py", line 93, in fedora_messaging_publish
remote:     topic,
remote: Message: 'pagure is about to send a message that has no schemas: pagure.%s'
remote: Arguments: ('git.receive',)
remote: 
remote: Create a pull-request for non-modular-ruby3.3
remote:    https://src.fedoraproject.org/fork/vondruch/rpms/ruby/diff/rawhide..non-modular-ruby3.3
remote: 
To ssh://pkgs.fedoraproject.org/forks/vondruch/rpms/ruby.git
   f49f4a7..bf1ad48  HEAD -> non-modular-ruby3.3

Seems like some permission issues or maybe Pagure out of space or something.


Metadata Update from @zlopez:
- Issue priority set to: Waiting on Assignee (was: Needs Review)
- Issue tagged with: Needs investigation, low-gain, ops

a year ago

It failed on trying to rotate log files. I checked your account and you should be able to do that as you are in correct packager group and the SELinux context seems fine as well. Is this happening every time you try to push?

Is this happening every time you try to push?

I have tried another push right now with the same issue.

Oh, now I also see this issue. Just I tried to do $ git push around 2024-Feb-08 20:05 (JST).

remote: PermissionError: [Errno 13] Permission denied: '/var/log/pagure/pagure_auth.log' -> '/var/log/pagure/pagure_auth.log.2024-02-07'
remote: Call stack:
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/files/post-receive", line 48, in <module>
remote:     run_hook_file(hooktype)
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/__init__.py", line 550, in run_hook_file
remote:     pull_request,
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/__init__.py", line 392, in run_project_hooks
remote:     changes=changes,
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/__init__.py", line 111, in runhook
remote:     changes=changes,
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/default.py", line 445, in post_receive
remote:     oldrev,
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/default.py", line 219, in send_notifications
remote:     pagure.lib.notify.blinker_publish(topic, msg)
remote:   File "/usr/lib/python3.6/site-packages/pagure/lib/notify.py", line 153, in blinker_publish
remote:     _log.info("Sending blinker signal to: pagure - topic: %s", topic)
remote: Message: 'Sending blinker signal to: pagure - topic: %s'
remote: Arguments: ('git.receive',)
remote: --- Logging error ---
remote: Traceback (most recent call last):
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 72, in emit
remote:     self.doRollover()
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 402, in doRollover
remote:     self.rotate(self.baseFilename, dfn)
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 113, in rotate
remote:     os.rename(source, dest)
remote: PermissionError: [Errno 13] Permission denied: '/var/log/pagure/pagure_auth.log' -> '/var/log/pagure/pagure_auth.log.2024-02-07'
remote: Call stack:
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/files/post-receive", line 48, in <module>
remote:     run_hook_file(hooktype)
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/__init__.py", line 550, in run_hook_file
remote:     pull_request,
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/__init__.py", line 392, in run_project_hooks
remote:     changes=changes,
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/__init__.py", line 111, in runhook
remote:     changes=changes,
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/default.py", line 445, in post_receive
remote:     oldrev,
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/default.py", line 222, in send_notifications
remote:     send_fedmsg_notifications(project, topic, msg)
remote:   File "/usr/lib/python3.6/site-packages/pagure/hooks/default.py", line 69, in send_fedmsg_notifications
remote:     pagure.lib.notify.fedora_messaging_publish(topic, msg)
remote:   File "/usr/lib/python3.6/site-packages/pagure/lib/notify.py", line 93, in fedora_messaging_publish
remote:     topic,
remote: Message: 'pagure is about to send a message that has no schemas: pagure.%s'
remote: Arguments: ('git.receive',)
To ssh://pkgs.fedoraproject.org/rpms/rubygem-minitest
   34d75e6..ae13795  rawhide -> rawhide

I think that previously, I have pushed something ~Jan 26 and that was without issues AFAIR

Let me check the pagure log, if there isn't anything

Metadata Update from @zlopez:
- Issue assigned to zlopez

a year ago

@vondruch Does the push itself works? Or it's blocking the push as well?

There is an issue with rotating pagure logs (hence, doRollover failing) due to inability to move /var/log/pagure_auth.log:

remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 72, in emit
remote:     self.doRollover()
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 402, in doRollover
remote:     self.rotate(self.baseFilename, dfn)
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 113, in rotate
remote:     os.rename(source, dest)
remote: PermissionError: [Errno 13] Permission denied: '/var/log/pagure/pagure_auth.log' -> '/var/log/pagure/pagure_auth.log.2024-02-07'

After some investigation I noticed that the group and permissions of the log folder are not set correctly. So I fixed that. It should now work without errors.

Reopen the ticket, if the error is still there.

Metadata Update from @zlopez:
- Issue close_status updated to: Fixed with Explanation
- Issue status updated to: Closed (was: Open)

a year ago

@vondruch Does the push itself works? Or it's blocking the push as well?

Yep, the push works.

Metadata Update from @vondruch:
- Issue status updated to: Open (was: Closed)

a year ago

Hmmm:

$ git push fork HEAD -f
Enumerating objects: 38, done.
Counting objects: 100% (35/35), done.
Delta compression using up to 8 threads
Compressing objects: 100% (28/28), done.
Writing objects: 100% (28/28), 9.09 KiB | 9.09 MiB/s, done.
Total 28 (delta 19), reused 0 (delta 0), pack-reused 0
remote: Traceback (most recent call last):
remote:   File "/usr/lib64/python3.6/logging/config.py", line 565, in configure
remote:     handler = self.configure_handler(handlers[name])
remote:   File "/usr/lib64/python3.6/logging/config.py", line 738, in configure_handler
remote:     result = factory(**kwargs)
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 205, in __init__
remote:     BaseRotatingHandler.__init__(self, filename, 'a', encoding, delay)
remote:   File "/usr/lib64/python3.6/logging/handlers.py", line 57, in __init__
remote:     logging.FileHandler.__init__(self, filename, mode, encoding, delay)
remote:   File "/usr/lib64/python3.6/logging/__init__.py", line 1032, in __init__
remote:     StreamHandler.__init__(self, self._open())
remote:   File "/usr/lib64/python3.6/logging/__init__.py", line 1061, in _open
remote:     return open(self.baseFilename, self.mode, encoding=self.encoding)
remote: PermissionError: [Errno 13] Permission denied: '/var/log/pagure/pagure_auth.log'
remote: 
remote: During handling of the above exception, another exception occurred:
remote: 
remote: Traceback (most recent call last):
remote:   File "hooks/pre-receive", line 45, in <module>
remote:     pagure.utils.set_up_logging(configkey=confkey)
remote:   File "/usr/lib/python3.6/site-packages/pagure/utils.py", line 46, in set_up_logging
remote:     logging.config.dictConfig(pagure_config.get(configkey) or {"version": 1})
remote:   File "/usr/lib64/python3.6/logging/config.py", line 802, in dictConfig
remote:     dictConfigClass(config).configure()
remote:   File "/usr/lib64/python3.6/logging/config.py", line 573, in configure
remote:     '%r: %s' % (name, e))
remote: ValueError: Unable to configure handler 'auth_handler': [Errno 13] Permission denied: '/var/log/pagure/pagure_auth.log'
To ssh://pkgs.fedoraproject.org/forks/vondruch/rpms/ruby.git
 ! [remote rejected] HEAD -> non-modular-ruby3.3 (pre-receive hook declined)
error: failed to push some refs to 'ssh://pkgs.fedoraproject.org/forks/vondruch/rpms/ruby.git'

Does not work for me either, with the same error as for @vondruch. It is basically couldn't open pagure_auth.log for write anymore.

I see what happened, let me fix that.

I forgot to set setgid flag to packager group, so the file was created under the first user that tried git push. So I set the file to packager group and added the setgid for log folder. It should work now.

I forgot to set setgid flag to packager group, so the file was created under the first user that tried git push. So I set the file to packager group and added the setgid for log folder. It should work now.

$ git push fork HEAD -f
Enumerating objects: 41, done.
Counting objects: 100% (38/38), done.
Delta compression using up to 8 threads
Compressing objects: 100% (31/31), done.
Writing objects: 100% (31/31), 9.40 KiB | 2.35 MiB/s, done.
Total 31 (delta 21), reused 0 (delta 0), pack-reused 0
remote: Sending to redis to log activity and send commit notification emails
remote: * Publishing information for 10 commits
remote:   - to fedora-message
remote: 2024-02-08 12:41:58,757 [WARNING] pagure.lib.notify: pagure is about to send a message that has no schemas: pagure.git.receive
remote: 
remote: Create a pull-request for non-modular-ruby3.3
remote:    https://src.fedoraproject.org/fork/vondruch/rpms/ruby/diff/rawhide..non-modular-ruby3.3
remote: 
To ssh://pkgs.fedoraproject.org/forks/vondruch/rpms/ruby.git
 + f760177...b035f3b HEAD -> non-modular-ruby3.3 (forced update)

Seems to work. Thx.

BTW it seems to me that you have fixed consequences, but was also the root cause addressed?

I didn't found out what was the root issue for this, but noticed that change of the permissions are part of playbook as hotfix. So I just assume that there was some update done on the machine that replaced the added permissions and the playbook wasn't run after that.

Metadata Update from @zlopez:
- Issue close_status updated to: Fixed with Explanation
- Issue status updated to: Closed (was: Open)

a year ago

Log in to comment on this ticket.

Metadata
Boards 1
ops Status: Backlog