UpdatePublicKey: Failed to update public key: public key does not exist

[gsantner]

• Gitea version (or commit ref): 7356762
• Git version: 2.11.0
• Operating system: Debian 9
• Database (use [x]):
  • PostgreSQL
  • MySQL
  • MSSQL
  • SQLite
• Can you reproduce the bug at https://try.gitea.io:
  • Yes (provide example URL)
  • No
  • Not relevant - no access
• Log gist:

Description

Sometimes i'm not able to pull from gitea because of anUpdatePublicKey error. As also the CI service pulls from gitea repos, this creates a lot of build errors every day. The keys are all added to the gitea account and do have access to repos. I also deleted, readded the keys and did a (gite admin)-ssh key rewrite.

gitea serv.log:

2017/06/25 19:04:18 [T] UpdatePublicKeyUpdated: http://localhost:5642/api/internal/ssh/20/update
2017/06/25 19:04:18 [...io/gitea/cmd/serv.go:329 runServ()] [F] UpdatePublicKey: Failed to update public key: public key does not exist [id: 20]

database entry (freshly added today):

INSERT INTO `public_key` (`id`, `owner_id`, `name`, `fingerprint`, `content`, `mode`, `type`, `created`, `updated`, `created_unix`, `updated_unix`) 
VALUES (20, 1, ' PubKeyName ', 'SHA256:arjdAAKEYAAAA COMMENT', 2, 1, NULL, NULL, 1498410219, 1498410258);

client:

Cloning the remote Git repository

Cloning repository gogs@SERVER:server/someone-wiki-jekyll.git

 > git init /var/lib/jenkins/workspace/someone-wiki-jekyll_master-ASIDHASDASF # timeout=10

Fetching upstream changes from gogs@SERVER:server/someone-wiki-jekyll.git

 > git --version # timeout=10

using GIT_SSH to set credentials Deploy jekyll wiki SSH

 > git fetch --tags --progress gogs@SERVER:server/someone-wiki-jekyll.git +refs/heads/*:refs/remotes/origin/*

ERROR: Error cloning remote repo 'origin'

hudson.plugins.git.GitException: Command "git fetch --tags --progress gogs@SERVER:server/someone-wiki-jekyll.git +refs/heads/*:refs/remotes/origin/*" returned status code 1:

stdout: 

stderr: remote: Zähle Objekte: 638, Fertig.        

remote: Komprimiere Objekte:   0% (1/286)           
remote: Komprimiere Objekte:   1% (3/286)          
....
remote: Komprimiere Objekte: 100% (286/286)           
remote: Komprimiere Objekte: 100% (286/286), Fertig.        

Empfange Objekte:   0% (1/638)   
Empfange Objekte:   1% (7/638)   
Empfange Objekte:   2% (13/638)   
...
Empfange Objekte:  46% (294/638)   
remote: Total 638 (delta 333), reused 610 (delta 322)        
....
Löse Unterschiede auf:  99% (332/333)   

Gitea: Internal error

UpdatePublicKey: Failed to update public key: public key does not exist [id: 20]


	at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.launchCommandIn(CliGitAPIImpl.java:1903)

	at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.launchCommandWithCredentials(CliGitAPIImpl.java:1622)

	at org.jenkinsci.plugins.gitclient.CliGitAPIImpl.access$300(CliGitAPIImpl.java:71)

[ethantkoenig]

@gsantner The INSERT command you posted isn't valid; the column count doesn't match the value count, and created and updated are not columns in the public_key table.

Are you sure there is a key with id 20 in the database (i.e. SELECT * FROM public_key WHERE id=20 returns something)?

If for some reason you're not able to directly run the SELECT command, you could instead use the GET /api/v1/users/:username/keys API endpoint to double-check that the key does in fact exist in the database.

[gsantner]

Sorry maybe I accidentally removed one during pasting to github. below is the export again.
Yes, the query gets exactly this line, so I'm sure theres ID 20 in there.

API: tried https://DOMAIN/gitea/api/v1/users/gregor/keys and it just shows me a white page without any error (accessed via browser). Theres also no error or other message in the log from this api query.
Did tail -f *.log inside code.gitea.io/gitea/log

in fact exist in the database.

It does, I directly accessed the database gitea is using.

As said above, I can access/clone/push. But sometimes (multiple times a day, and often at CI) it just gives this error. The keys are correctly setted up at my clients.

--
-- Tabellenstruktur für Tabelle `public_key`
--

CREATE TABLE `public_key` (
  `id` bigint(20) NOT NULL,
  `owner_id` bigint(20) NOT NULL,
  `name` varchar(255) NOT NULL,
  `fingerprint` varchar(255) NOT NULL,
  `content` text NOT NULL,
  `mode` int(11) NOT NULL DEFAULT '2',
  `type` int(11) NOT NULL DEFAULT '1',
  `created` datetime DEFAULT NULL,
  `updated` datetime DEFAULT NULL,
  `created_unix` bigint(20) DEFAULT NULL,
  `updated_unix` bigint(20) DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

--
-- Daten für Tabelle `public_key`
--

INSERT INTO `public_key` (`id`, `owner_id`, `name`, `fingerprint`, `content`, `mode`, `type`, `created`, `updated`, `created_unix`, `updated_unix`) VALUES
(20, 1, ' laptop gregor ', 'SHA256:arjdRrafsdfsdfadsfsd', 'ssh-rsa AAAasdfadsfadsfadsfadsfjr9F gregor@somewhere', 2, 1, NULL, NULL, 1498410219, 1498468069);

[ethantkoenig]

@gsantner What is the value of setting.LocalURL in your setup (specifically inside the serv subcommand)?

The request POST {setting.LocalURL}/api/internal/ssh/20/update (made here) is returning a 500, because whatever gitea instance is running at that URL is talking to a different database than the one that contains your key.

[gsantner]

I dont have any debugging tools or like that installed on the system. What shall I do, and where I can find the piece of information then?

[gsantner]

Btw: There is just one Gitea instance running on the system

[ethantkoenig]

@gsantner From looking at the logs you've posted, setting.LocalURL is http://localhost:5642. Can do you the following:

1. Can you double-check that the gitea config (default location is custom/conf/app.ini) is correct? Specifically the database config?
2. Can you go to http://localhost:5642/user/settings/keys (authenticated as the user with id 1), and confirm that you see the key you inserted (SHA256:arjdRrafsdfsdfadsfsd)

If neither of these reveal anything, then I'm stuck 😕

[gsantner]

1 ) Well, it's localhost at a port yes, but apache is serving in front. (Which shouldn't matter anyway as I'm cloning via SSH)

[server]
SSH_DOMAIN   =  MY.DOMAIN.EXT
DOMAIN       = MY.DOMAIN.EXT
HTTP_PORT    = 5642    
ROOT_URL     = https://MY.DOMAIN.EXT/gitea
OFFLINE_MODE = false
ENABLE_GZIP  = false

[database]
DB_TYPE  = mysql
HOST     = 127.0.0.1:3306
NAME     = gitea
USER     = gitea
PASSWD   = PASS

2. Of course, yeah, the right key (hash) is there (I pasted some short random text in the issue). And in the database too. With the correct text and description.

[lafriks]

Does in your app.ini config file has INTERNAL_TOKEN value?

[gsantner]

@lafriks Yep, under [security]

[lafriks]

and it is not empty, right? (do not post it here just confirm it is not empty)

[gsantner]

of course it is there

[lunny]

Could you reproduce that? Maybe take a look at the xorm.log?

[gsantner]

Yes, reproducible. serv.log.txt / xorm.log.txt. I deleted all logs before starting the script.

Maybe some kind of race condition? Maybe related to a timestamp?

#!/bin/bash
for i in `seq 1 100` ; do 
        git clone gogs@myhost:me/somerepo.git   CloneNr$i 2>&1 | grep "key" &
done
ls | wc -l

outputs: (59 clones out of 100 worked actually / loaded repo fully).

$
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
UpdatePublicKey: Failed to update public key: public key does not exist [id: 19]
59

[lafriks]

Thanks for detailed info, I will look into this

[gsantner]

@lafriks
Thanks for your fixes! Tried the script above again, and there are no warnings/erorrs anymore now. But still about half of the clones do not work.

[gregor@gregor-desktop aatmp]$ bash clonestuff.sh ; sleep 5 ; rmFolderWithGit clone
83
[gregor@gregor-desktop aatmp]$ bash clonestuff.sh ; sleep 5 ; rmFolderWithGit clone
80
[gregor@gregor-desktop aatmp]$ 
[gregor@gregor-desktop aatmp]$ bash clonestuff.sh ; sleep 5 ; rmFolderWithGit clone
22
[gregor@gregor-desktop aatmp]$ bash clonestuff.sh ; sleep 5 ; rmFolderWithGit clone
30
[gregor@gregor-desktop aatmp]$ bash clonestuff.sh ; sleep 5 ; rmFolderWithGit clone
88
[gregor@gregor-desktop aatmp]$ bash clonestuff.sh ; sleep 5 ; rmFolderWithGit clone
50
[gregor@gregor-desktop aatmp]$ bash clonestuff.sh ; sleep 5 ; rmFolderWithGit clone
40
[gregor@gregor-desktop aatmp]$ bash clonestuff.sh ; sleep 5 ; rmFolderWithGit clone
67

In the Logs I can find
2017/07/20 16:15:08 [T] UpdatePublicKeyUpdated: http://localhost:PORT/api/internal/ssh/19/update lines, but no public key error anymore. I don't know where the problem lies now, but there is still a bug.
The problem may not occur so often when using it with one time push/pull for code updates, but if theres e.g. jenkins behind who does pull and make checks

[lafriks]

@gsantner It works correctly wait before bash script finishes to execute and than check cloned repository count. Because at the end of git clone you have & so ls executes faster than git commands are finished cloning repositories that's way you get wrong count. If you will wait a bit longer and run ls manually you will see correct count

[gsantner]

Thats what I tried too (before multiple script execution). fail2ban turned off. heres a log. I did check if some git is running too

log.txt

I tried the script too with 10 clones, that works. 100 may be a little heavy and unnatural, I'm just somewhat suprised it cannot be handled even if cloning is running from/to localhost. From the log: maybe an upstream bug in openssh?

[lafriks]

@gsantner try adding sleep before ls, might be that when scripts exits it child processes are also killed

[gsantner]

I did execute the commands manually after some time. as said, I'm sure no git clone was running. (At the multi-test two above yes, but not in the manual clones where the log comes from.) [log.txt](https://github.com/go-gitea/gitea/files/1163090/log.txt) Am 20. Juli 2017 18:18:31 MESZ schrieb Lauris BH <notifications@github.com>:

…

@gsantner try adding sleep before ls, might be that when scripts exits it child processes are also killed -- You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: #2060 (comment)

-- Diese Nachricht wurde von meinem Android-Gerät mit K-9 Mail gesendet.

[lafriks]

@gsantner I found out why are you having problem with 100 parallel clones. It is actually not a gitea fault but ssh servers anti ddos protection. By default ssh configuration has MaxStartups 10:30:60 that means that it will start drop connections at rate 30% after it has 10 parallel yet unauthorized connections or more than 60 connections in total. When setting MaxStartups 100:30:120 in /etc/ssh/sshd_config and restarting ssh server I had no problems and all 100 copies get cloned without errors.

[gsantner]

@lafriks Wow, thanks for finding that out 👍, and of course for fixing the bug