Lost packages after publication

[ishaulov]

Hi! After resolved #1276 I builded and installed aptly version 1.5.0+207+g372ce3c4

And now some big packages (>900 Mb) are lost with concurent builds on Jenkins.
When uploading and publishing the package I get status 2, but the package is not in the repository.
For example, the package testfile_4.4.5.7667 was lost.

Please, help me understand, why this is happening?

root@testrepo:~# aptly repo show -with-packages testrepo
testfile_4.4.5.7665_amd64
testfile-archive-_4.4.5.7667_amd64
testfile-long-data_4.4.5.7667_amd64

In aptly access.log file:

"level":"info","remote":"192.168.100.113","method":"POST","path":"/api/repos/testrepo/file/tmp.U5FXf4EUJcvNTWu/testfile_4.4.5.7667_amd64.deb?_async=true","protocol":"HTTP/1.0","code":"202","latency":"231.621µs","agent":"curl/7.58.0","time":"2024-10-20T22:56:47+05:00"}

In Jenkins console output:

23:08:36 + publish_output='+++ mktemp -d tmp.XXXXXXXXXXXXXXX
23:08:36 ++ upload_folder=tmp.U5FXf4EUJcvNTWu
23:08:36 ++ curl -f -X POST -F file=@/home/lnxbuilder/7667/deb//testfile_4.4.5.7667_amd64.deb http://localrepo.com/deb/api/files/tmp.U5FXf4EUJcvNTWu -u login:pass
23:08:36 ++ json_pp
23:08:36   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
23:08:36                                  Dload  Upload   Total   Spent    Left  Speed
23:08:36 
23:08:36   0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
23:08:36   0 1738M    0     0    0  480k      0  18.0M  0:01:36 --:--:--  0:01:36 18.0M
23:08:36   2 1738M    0     0    2 51.0M      0  49.7M  0:00:34  0:00:01  0:00:33 49.7M
23:08:36   5 1738M    0     0    5  101M      0  50.1M  0:00:34  0:00:02  0:00:32 50.1M
23:08:36  10 1738M    0     0   10  182M      0  60.1M  0:00:28  0:00:03  0:00:25 60.1M
23:08:36  16 1738M    0     0   16  283M      0  70.3M  0:00:24  0:00:04  0:00:20 70.3M
23:08:36  22 1738M    0     0   22  384M      0  76.4M  0:00:22  0:00:05  0:00:17 76.8M
23:08:36  27 1738M    0     0   27  485M      0  80.5M  0:00:21  0:00:06  0:00:15 86.9M
23:08:36  33 1738M    0     0   33  585M      0  83.3M  0:00:20  0:00:07  0:00:13 96.7M
23:08:36  39 1738M    0     0   39  686M      0  85.5M  0:00:20  0:00:08  0:00:12  100M
23:08:36  45 1738M    0     0   45  787M      0  87.2M  0:00:19  0:00:09  0:00:10  100M
23:08:36  51 1738M    0     0   51  888M      0  88.6M  0:00:19  0:00:10  0:00:09  100M
23:08:36  56 1738M    0     0   56  990M      0  89.8M  0:00:19  0:00:11  0:00:08  100M
23:08:36  62 1738M    0     0   62 1091M      0  90.7M  0:00:19  0:00:12  0:00:07  101M
23:08:36  68 1738M    0     0   68 1192M      0  91.5M  0:00:18  0:00:13  0:00:05  101M
23:08:36  74 1738M    0     0   74 1293M      0  92.2M  0:00:18  0:00:14  0:00:04  101M
23:08:36  80 1738M    0     0   80 1394M      0  92.8M  0:00:18  0:00:15  0:00:03  101M
23:08:36  86 1738M    0     0   86 1496M      0  93.3M  0:00:18  0:00:16  0:00:02  101M
23:08:36  91 1738M    0     0   91 1597M      0  93.8M  0:00:18  0:00:17  0:00:01  101M
23:08:36  97 1738M    0     0   97 1698M      0  94.2M  0:00:18  0:00:18 --:--:--  101M
23:08:36 100 1738M    0     0  100 1738M      0  89.5M  0:00:19  0:00:19 --:--:-- 82.4M
23:08:36 100 1738M    0     0  100 1738M      0  85.1M  0:00:20  0:00:20 --:--:-- 63.6M
23:08:36 100 1738M    0     0  100 1738M      0  81.1M  0:00:21  0:00:21 --:--:-- 44.8M
23:08:36 100 1738M    0     0  100 1738M      0  77.5M  0:00:22  0:00:22 --:--:-- 26.1M
23:08:36 100 1738M    0     0  100 1738M      0  74.2M  0:00:23  0:00:23 --:--:-- 7531k
23:08:36 100 1738M  100    74  100 1738M      3  72.9M  0:00:24  0:00:23  0:00:01    16
23:08:36 [
23:08:36    "tmp.U5FXf4EUJcvNTWu/testfile_4.4.5.7667_amd64.deb"
23:08:36 ]
23:08:36 +++ curl -f -X POST '\''http://localrepo.com/deb/api/repos/testrepo/file/tmp.U5FXf4EUJcvNTWu/testfile_4.4.5.7667_amd64.deb?_async=true'\'' -u login:pass
23:08:36 +++ json_pp
23:08:36   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
23:08:36                                  Dload  Upload   Total   Spent    Left  Speed
23:08:36 
23:08:36   0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
23:08:36 100   136  100   136    0     0   1225      0 --:--:-- --:--:-- --:--:--  1225
23:08:36 ++ response='\''{
23:08:36    "State" : 0,
23:08:36    "ID" : 61,
23:08:36    "Name" : "Add package testfile_4.4.5.7667_amd64.deb from dir tmp.U5FXf4EUJcvNTWu to repo testrepo"
23:08:36 }'\''
23:08:36 +++ echo '\''{
23:08:36    "State" : 0,
23:08:36    "ID" : 61,
23:08:36    "Name" : "Add package testfile_4.4.5.7667_amd64.deb from dir tmp.U5FXf4EUJcvNTWu to repo testrepo"
23:08:36 }'\''
23:08:36 +++ jq -r .ID
23:08:36 ++ task_id=61
23:08:36 +++ curl -f http://localrepo.com/deb/api/tasks/61/wait -u login:pass
23:08:36   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
23:08:36                                  Dload  Upload   Total   Spent    Left  Speed
23:08:36 
23:08:36   0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:01 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:02 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:03 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:04 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:05 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:06 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:07 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:08 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:09 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:10 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:11 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:12 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:13 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:14 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:15 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:16 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:17 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:18 --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:19 --:--:--     0
23:08:36 100   136  100   136    0     0      6      0  0:00:22  0:00:19  0:00:03    30
23:08:36 ++ status_response='\''{"Name":"Add package testfile_4.4.5.7667_amd64.deb from dir tmp.U5FXf4EUJcvNTWu to repo testrepo","ID":61,"State":2}'\''
23:08:36 +++ echo '\''{"Name":"Add package testfile_4.4.5.7667_amd64.deb from dir tmp.U5FXf4EUJcvNTWu to repo testrepo","ID":61,"State":2}'\''
23:08:36 +++ jq -r .State
23:08:36 ++ state=2
23:08:36 ++ echo '\''Upload package with state: 2'\''
23:08:36 Upload package with state: 2
23:08:36 ++ for repo_name in "${repo_names[@]}"
23:08:36 ++ publish_deb_repo testrepo
23:08:36 ++ local repo_name=testrepo
23:08:36 +++ curl -f -X PUT '\''http://localrepo.com/deb/api/publish/:./testrepo?_async=true'\'' -H '\''Content-Type: application/json'\'' --data '\''{"Signing":{"Batch":true,"GpgKey":"DBaaaaaa", "Passphrase":"aaaaaaa"}}'\'' -u login:pass
23:08:36 +++ json_pp
23:08:36   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
23:08:36                                  Dload  Upload   Total   Spent    Left  Speed
23:08:36 
23:08:36   0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
23:08:36 100   167  100    60  100   107   3750   6687 --:--:-- --:--:-- --:--:-- 10437
23:08:36 ++ response='\''{
23:08:36    "ID" : 63,
23:08:36    "State" : 0,
23:08:36    "Name" : "Update published local (main): "
23:08:36 }'\''
23:08:36 +++ echo '\''{
23:08:36    "ID" : 63,
23:08:36    "State" : 0,
23:08:36    "Name" : "Update published local (main): "
23:08:36 }'\''
23:08:36 +++ jq -r .ID
23:08:36 ++ task_id=63
23:08:36 +++ curl -f http://localrepo.com/deb/api/tasks/63/wait -u login:pass
23:08:36   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
23:08:36                                  Dload  Upload   Total   Spent    Left  Speed
23:08:36 
23:08:36   0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
23:08:36   0     0    0     0    0     0      0      0 --:--:--  0:00:01 --:--:--     0
23:08:49   0     0    0     0    0     0      0      0 --:--:--  0:00:02 --:--:--     0
23:08:49   0     0    0     0    0     0      0      0 --:--:--  0:00:03 --:--:--     0
23:08:49   0     0    0     0    0     0      0      0 --:--:--  0:00:04 --:--:--     0
23:08:49   0     0    0     0    0     0      0      0 --:--:--  0:00:05 --:--:--     0
23:08:49   0     0    0     0    0     0      0      0 --:--:--  0:00:06 --:--:--     0
23:08:49   0     0    0     0    0     0      0      0 --:--:--  0:00:07 --:--:--     0
23:08:49   0     0    0     0    0     0      0      0 --:--:--  0:00:08 --:--:--     0
23:08:50   0     0    0     0    0     0      0      0 --:--:--  0:00:09 --:--:--     0
23:08:50   0     0    0     0    0     0      0      0 --:--:--  0:00:10 --:--:--     0
23:08:59   0     0    0     0    0     0      0      0 --:--:--  0:00:11 --:--:--     0
23:09:08   0     0    0     0    0     0      0      0 --:--:--  0:00:12 --:--:--     0
23:09:08   0     0    0     0    0     0      0      0 --:--:--  0:00:13 --:--:--     0
23:09:08   0     0    0     0    0     0      0      0 --:--:--  0:00:14 --:--:--     0
23:09:08   0     0    0     0    0     0      0      0 --:--:--  0:00:15 --:--:--     0
23:09:08   0     0    0     0    0     0      0      0 --:--:--  0:00:16 --:--:--     0
23:09:08   0     0    0     0    0     0      0      0 --:--:--  0:00:17 --:--:--     0
23:09:08   0     0    0     0    0     0      0      0 --:--:--  0:00:18 --:--:--     0
23:09:08   0     0    0     0    0     0      0      0 --:--:--  0:00:19 --:--:--     0
23:11:06   0     0    0     0    0     0      0      0 --:--:--  0:00:20 --:--:--     0
23:11:06   0     0    0     0    0     0      0      0 --:--:--  0:00:21 --:--:--     0
23:11:06   0     0    0     0    0     0      0      0 --:--:--  0:00:22 --:--:--     0
23:11:06   0     0    0     0    0     0      0      0 --:--:--  0:00:23 --:--:--     0
23:11:06   0     0    0     0    0     0      0      0 --:--:--  0:00:24 --:--:--     0
23:11:06   0     0    0     0    0     0      0      0 --:--:--  0:00:25 --:--:--     0
23:11:06   0     0    0     0    0     0      0      0 --:--:--  0:00:26 --:--:--     0
23:11:06 100    60  100    60    0     0      2      0  0:00:30  0:00:27  0:00:03    12
23:11:06 100    60  100    60    0     0      2      0  0:00:30  0:00:27  0:00:03    15
23:11:12 ++ status_response='\''{"Name":"Update published local (main): ","ID":63,"State":2}'\''
23:11:12 +++ echo '\''{"Name":"Update published local (main): ","ID":63,"State":2}'\''
23:11:12 +++ jq -r .State
23:11:12 ++ state=2
23:11:12 ++ echo '\''Publication complete with state: 2'\''
23:12:45 Publication complete with state: 2

[neolynx]

Hi !

The Jenkins output looks ok to me... this is just one of the parallel runs ?

some more questions:

Does each run use a unique upload dir (tmp.U5FXf4EUJcvNTWu) ?
Are the 3 files uploaded concurrently ?
What do you mean by the package is not in the repository ?

[ishaulov]

@neolynx hi!

1. yes, this is just one of parallel;
2. yes, I use upload_folder=$(mktemp -d tmp.XXXXXXXXXXXXXXX)
3. I removed some of the packages from the output. There are actually 11 packages loaded sequentially in this build and another 11 packages loaded in a parallel build on Jenkins;
4. I can see from the output that the package has been successfully downloaded (status 2), but when aptly repo show -with-packages testrepo outputs the package of the version I need is not there, there is no package on the repository web page, and when apt install testfile=4.4.5.7667 there is no such package either.

[neolynx]

thanks for the explanations !

I think I found the race condition: async background operation was not implemented to do all database operation inside a synchronized block, so for example adding a directory to a repo would read the repo contents, and then run the background tasks. If 2 run at the same time, the could both read a emptry repo, and then in the background operation, on of them wins.

since you are compiling aptly, could you try commit f16a68f from the branch fix/concurrent-api ?

this should fix most race conditions (except maybe deleting the repo while adding files)

[neolynx]

fix has been merged to master... please test again !

[ishaulov]

fix has been merged to master... please test again !

Oh! Thanks! :-)
I'll be able to check in a day or two and will come back with feedback!

[ishaulov]

@neolynx I built aptly from master and tested it. Everything works perfectly!
Thank you very much for your help! 😃

[neolynx]

thank you for finding and reproducing this !