Snap Store Server

firefox: Cannot submit xdelta snap: "Delta service failed to apply delta successfully"

Bug #1793752 reported by Johan Lorenzo
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Mozilla Firefox
Fix Released
Medium
Snap Store Server
Fix Released
High
William Grant

Bug Description

Hello,

I tried to activate xdelta3 Snap on Firefox, but it seems I ran into an issue. I don't have much more context than the following logs (in UTC). Would you guys have more on the server side?

2018-09-21T13:03:08 INFO - 2018-09-21 13:03:08,194 - snapcraft.internal.common - DEBUG - snapcraft is running as a snap False, SNAP_NAME set to ''
2018-09-21T13:03:08 INFO - 2018-09-21 13:03:08,241 - snapcraft._store - DEBUG - b'Parallel unsquashfs: Using 1 processor\n1 inodes (1 blocks) to write\n\n\r[===================================================================|] 1/1 100%\n\ncreated 1 files\ncreated 2 directories\ncreated 0 symlinks\ncreated 0 devices\ncreated 0 fifos\n'
2018-09-21T13:03:08 INFO - 2018-09-21 13:03:08,264 - snapcraft._store - INFO - Preparing to push '/builds/scriptworker/work/cot/BtwB6HZZTCSL2KbfPCTRzg/public/build/target.snap' to the store.
2018-09-21T13:03:08 INFO - 2018-09-21 13:03:08,705 - snapcraft._store - INFO - Found cached source snap /home/cltbld/.cache/snapcraft/projects/firefox/snap_hashes/amd64/eeaf6383120aefcc51d291a8065ea2a2dbfd0f82d43daafaa6b6278fb3ba712f8a3f04bfa77710060b5ae18c96d11f39.
2018-09-21T13:03:08 INFO - 2018-09-21 13:03:08,706 - snapcraft.internal.common - DEBUG - snapcraft is running as a snap False, SNAP_NAME set to ''
2018-09-21T13:03:08 INFO - 2018-09-21 13:03:08,707 - snapcraft.internal.deltas._deltas - INFO - Generating xdelta3 delta for target.snap.
2018-09-21T13:03:50 INFO - 2018-09-21 13:03:50,803 - snapcraft.internal.deltas._xdelta3 - DEBUG - xdelta3 delta diff generation:
2018-09-21T13:03:50 INFO - VCDIFF version: 0
2018-09-21T13:03:50 INFO - VCDIFF header size: 117
2018-09-21T13:03:50 INFO - VCDIFF header indicator: VCD_SECONDARY VCD_APPHEADER
2018-09-21T13:03:50 INFO - VCDIFF secondary compressor: lzma
2018-09-21T13:03:50 INFO - VCDIFF application header: target.snap//eeaf6383120aefcc51d291a8065ea2a2dbfd0f82d43daafaa6b6278fb3ba712f8a3f04bfa77710060b5ae18c96d11f39/
2018-09-21T13:03:50 INFO - XDELTA filename (output): target.snap
2018-09-21T13:03:50 INFO - XDELTA filename (source): eeaf6383120aefcc51d291a8065ea2a2dbfd0f82d43daafaa6b6278fb3ba712f8a3f04bfa77710060b5ae18c96d11f39
2018-09-21T13:03:50 INFO - VCDIFF window number: 0
2018-09-21T13:03:50 INFO - VCDIFF window indicator: VCD_SOURCE VCD_ADLER32
2018-09-21T13:03:50 INFO - VCDIFF adler32 checksum: EAE474AE
2018-09-21T13:03:50 INFO - VCDIFF delta indicator: VCD_DATACOMP VCD_INSTCOMP VCD_ADDRCOMP
2018-09-21T13:03:50 INFO - VCDIFF copy window length: 67095762
2018-09-21T13:03:50 INFO - VCDIFF copy window offset: 0
2018-09-21T13:03:50 INFO - VCDIFF delta encoding length: 6467032
2018-09-21T13:03:50 INFO - VCDIFF target window length: 8388608
2018-09-21T13:03:50 INFO - VCDIFF data section length: 6464267
2018-09-21T13:03:50 INFO - VCDIFF inst section length: 1462
2018-09-21T13:03:50 INFO - VCDIFF addr section length: 1286
2018-09-21T13:03:50 INFO -
2018-09-21T13:03:53 INFO - 2018-09-21 13:03:53,855 - snapcraft._store - INFO - Pushing delta /builds/scriptworker/work/cot/BtwB6HZZTCSL2KbfPCTRzg/public/build/target.snap.xdelta3.
Pushing target.snap.xdelta3 [============================================] 100%
Processing...|
2018-09-21T13:04:13 INFO - 2018-09-21 13:04:13,786 - snapcraft._store - WARNING - Error generating delta: There has been a problem while processing a snap delta.
2018-09-21T13:04:13 INFO - - Delta service failed to apply delta successfully
2018-09-21T13:04:13 INFO - Falling back to pushing full snap...
Pushing target.snap [====================================================] 100%

Revision history for this message
In , Jlorenzo-m (jlorenzo-m) wrote :

We could generate delta updates for snap, if we had xdelta3 installed on the machine[1][2]:

> 2018-04-09 22:35:51,286 - snapcraft._store - INFO - Found cached source snap /home/cltbld/.cache/snapcraft/projects/firefox/snap_hashes/amd64/1549949fa22a73acbeace379745171095cfd8c122f9109851bf76c326a0119fa560db41b0a785b390009936ae861fc3c.
> 2018-04-09 22:35:51,288 - snapcraft._store - WARNING - Error generating delta: delta_tool_path must be set in subclass!

Sadly, we have to make the package ourselves. There is no rpm available per [3]

[1] https://tools.taskcluster.net/groups/BH0QdNzbQ8iLXlM28cQ4jw/tasks/Vm7C-ovDSMOLlEuT1dQEVA/runs/0/logs/public%2Flogs%2Flive_backing.log#L12
[2] https://github.com/snapcore/snapcraft/blob/c59977709262f8c960fd0ebbafc9e7799093109e/snapcraft/internal/deltas/_xdelta3.py#L29-L30
[3] https://pkgs.org/download/xdelta3

Revision history for this message
In , Jlorenzo-m (jlorenzo-m) wrote :

Bug 1493053 made me install xdelta3 on the worker. However, something went wrong on the Store side[1]. The logs don't say much more than:

> 2018-09-21T13:03:53 INFO - 2018-09-21 13:03:53,855 - snapcraft._store - INFO - Pushing delta /builds/scriptworker/work/cot/BtwB6HZZTCSL2KbfPCTRzg/public/build/target.snap.xdelta3.
> Pushing target.snap.xdelta3 [============================================] 100%
Processing...|
> 2018-09-21T13:04:13 INFO - 2018-09-21 13:04:13,786 - snapcraft._store - WARNING - Error generating delta: There has been a problem while processing a snap delta.
> 2018-09-21T13:04:13 INFO - - Delta service failed to apply delta successfully
> 2018-09-21T13:04:13 INFO - Falling back to pushing full snap...

I filed https://bugs.launchpad.net/snapstore/+bug/1793752 to get more input.

[1] https://tools.taskcluster.net/groups/CTU6CA-PTGyDBu4IExIgoA/tasks/USJ2lRdtQ16waOO0kzT-zw/runs/2/logs/public%2Flogs%2Flive_backing.log#L198

Revision history for this message
Daniel Manrique (roadmr) wrote :

Hi Johan,

This appears to have been a transient error downloading the source snap to apply the delta :(

If possible, give this a try on your next Firefox upload, it should work better. If not, please let me know (the log you posted was great because with the source snap hash I was able to track this in our logs easily).

I've filed a private bug with the server-side traceback (because it contains a bunch of secret-looking tokens), so we'll look at it anyway.

Changed in snapstore:
status: New → Confirmed
importance: Undecided → High
Revision history for this message
Johan Lorenzo (johanlorenzo) wrote :

Thank you Daniel for the context!

I have some good news: thanks to the fallback mechanism allowed me to activate xdelta on every Snap we push. So xdelta is tried at least twice a week: on the (UTC) night between Monday and Tuesday, then on the (UTC) between Thursday and Friday.

I'll past some new logs tomorrow. Do you need everything I pasted above? Or is a hash like "eeaf6383120aefcc51d291a8065ea2a2dbfd0f82d43daafaa6b6278fb3ba712f8a3f04bfa77710060b5ae18c96d11f39" enough for you?

Revision history for this message
Johan Lorenzo (johanlorenzo) wrote :

Here's last night's try:

2018-10-01 22:11:35,489 - snapcraft._store - INFO - Found cached source snap /home/cltbld/.cache/snapcraft/projects/firefox/snap_hashes/amd64/34e1c1cc8eecd87868f6409d75a156d9404154e7acb7a6120aba0b2075286459b614c6a254431c4f15e335825c38c52b.
2018-10-01 22:11:35,490 - snapcraft.internal.common - DEBUG - snapcraft is running as a snap False, SNAP_NAME set to ''
2018-10-01 22:11:35,493 - snapcraft.internal.deltas._deltas - INFO - Generating xdelta3 delta for target.snap.
2018-10-01 22:12:17,815 - snapcraft.internal.deltas._xdelta3 - DEBUG - xdelta3 delta diff generation:
VCDIFF version: 0
VCDIFF header size: 117
VCDIFF header indicator: VCD_SECONDARY VCD_APPHEADER
VCDIFF secondary compressor: lzma
VCDIFF application header: target.snap//34e1c1cc8eecd87868f6409d75a156d9404154e7acb7a6120aba0b2075286459b614c6a254431c4f15e335825c38c52b/
XDELTA filename (output): target.snap
XDELTA filename (source): 34e1c1cc8eecd87868f6409d75a156d9404154e7acb7a6120aba0b2075286459b614c6a254431c4f15e335825c38c52b
VCDIFF window number: 0
VCDIFF window indicator: VCD_SOURCE VCD_ADLER32
VCDIFF adler32 checksum: 27CB82A2
VCDIFF delta indicator: VCD_DATACOMP VCD_INSTCOMP VCD_ADDRCOMP
VCDIFF copy window length: 66894114
VCDIFF copy window offset: 0
VCDIFF delta encoding length: 6381572
VCDIFF target window length: 8388608
VCDIFF data section length: 6378979
VCDIFF inst section length: 1350
VCDIFF addr section length: 1226

2018-10-01 22:12:20,841 - snapcraft._store - INFO - Pushing delta /builds/scriptworker/work/cot/XDM1xoB8RCK0pSzqbxpUxw/public/build/target.snap.xdelta3.
Pushing target.snap.xdelta3 [============================================] 100%
Processing...|
2018-10-01 22:12:37,916 - snapcraft._store - WARNING - Error generating delta: There has been a problem while processing a snap delta.
  - Delta service failed to apply delta successfully
Falling back to pushing full snap...

Revision history for this message
William Grant (wgrant) wrote :

Delta service logs for that upload (Canonical-internal only): https://pastebin.canonical.com/p/yXYvc5RNmy/

I can't find a corresponding request in the CUD appserver logs, so we'll have to dig into the frontend stack.

Revision history for this message
William Grant (wgrant) wrote :

Delta uploads should be reliable now. Let us know if you run into any further failures.

Changed in snapstore:
assignee: nobody → William Grant (wgrant)
status: Confirmed → Fix Released
Bug Watch Updater (bug-watch-updater)
Changed in firefox:
importance: Unknown → Medium
status: Unknown → Confirmed
Revision history for this message
Johan Lorenzo (johanlorenzo) wrote :
Download full text (9.2 KiB)

Hi there!

Sorry, I realized I've never followed up on this ticket. I confirm it works! Here's our most recent push:

2019-09-03 08:58:19,518 - snapcraft.internal.deltas._xdelta3 - DEBUG - xdelta3 delta diff generation:
VCDIFF version: 0
VCDIFF header size: 117
VCDIFF header indicator: VCD_SECONDARY VCD_APPHEADER
VCDIFF secondary compressor: lzma
VCDIFF application header: target.snap//c553f2f91fffe9cd02110d31620942db7babee02bac5d73dbb303f55cd43b02fa30becd888d4e5887c3949177bfa45ca/
XDELTA filename (output): target.snap
XDELTA filename (source): c553f2f91fffe9cd02110d31620942db7babee02bac5d73dbb303f55cd43b02fa30becd888d4e5887c3949177bfa45ca
VCDIFF window number: 0
VCDIFF window indicator: VCD_SOURCE VCD_ADLER32
VCDIFF adler32 checksum: B13BFA3D
VCDIFF delta indicator: VCD_DATACOMP VCD_INSTCOMP VCD_ADDRCOMP
VCDIFF copy window length: 66951984
VCDIFF copy window offset: 0
VCDIFF delta encoding length: 7431080
VCDIFF target window length: 8388608
VCDIFF data section length: 7427894
VCDIFF inst section length: 1794
VCDIFF addr section length: 1375

2019-09-03 08:58:27,988 - snapcraft._store - INFO - Pushing delta /builds/scriptworker/work/cot/M3vBcSoISlKtTAOitQ9tmQ/public/build/target.snap.xdelta3.
Pushing target.snap.xdelta3 [ ] 0%
Pushing target.snap.xdelta3 [ ] 1%
Pushing target.snap.xdelta3 [ ] 2%
Pushing target.snap.xdelta3 [= ] 3%
Pushing target.snap.xdelta3 [= ] 4%
Pushing target.snap.xdelta3 [== ] 5%
Pushing target.snap.xdelta3 [== ] 6%
Pushing target.snap.xdelta3 [=== ] 7%
Pushing target.snap.xdelta3 [=== ] 8%
Pushing target.snap.xdelta3 [=== ] 9%
Pushing target.snap.xdelta3 [==== ] 10%
Pushing target.snap.xdelta3 [==== ] 11%
Pushing target.snap.xdelta3 [===== ] 12%
Pushing target.snap.xdelta3 [===== ] 13%
Pushing target.snap.xdelta3 [====== ] 14%
Pushing target.snap.xdelta3 [====== ] 15%
Pushing target.snap.xdelta3 [======= ] 16%
Pushing target.snap.xdelta3 [======= ] 17%
Pushing target.snap.xdelta3 [======= ] 18%
Pushing target.snap.xdelta3 [======== ] 19%
Pushing target.snap.xdelta3 [======== ] 20%
Pushing target.snap.xdelta3 [========= ] 21%
Pushing target.snap.xdelta3 [========= ] 22%
Pushing target.snap.xdelta3 [========== ...

Read more...

Revision history for this message
In , Jlorenzo-m (jlorenzo-m) wrote :
Download full text (7.1 KiB)

I realized I've never came back to this bug. The Canonical folks fixed it a while ago 😃 Like I said in [1], our most recent push looks great[2]:

```
2019-09-03 08:58:19,518 - snapcraft.internal.deltas._xdelta3 - DEBUG - xdelta3 delta diff generation:
VCDIFF version: 0
VCDIFF header size: 117
VCDIFF header indicator: VCD_SECONDARY VCD_APPHEADER
VCDIFF secondary compressor: lzma
VCDIFF application header: target.snap//c553f2f91fffe9cd02110d31620942db7babee02bac5d73dbb303f55cd43b02fa30becd888d4e5887c3949177bfa45ca/
XDELTA filename (output): target.snap
XDELTA filename (source): c553f2f91fffe9cd02110d31620942db7babee02bac5d73dbb303f55cd43b02fa30becd888d4e5887c3949177bfa45ca
VCDIFF window number: 0
VCDIFF window indicator: VCD_SOURCE VCD_ADLER32
VCDIFF adler32 checksum: B13BFA3D
VCDIFF delta indicator: VCD_DATACOMP VCD_INSTCOMP VCD_ADDRCOMP
VCDIFF copy window length: 66951984
VCDIFF copy window offset: 0
VCDIFF delta encoding length: 7431080
VCDIFF target window length: 8388608
VCDIFF data section length: 7427894
VCDIFF inst section length: 1794
VCDIFF addr section length: 1375

2019-09-03 08:58:27,988 - snapcraft._store - INFO - Pushing delta /builds/scriptworker/work/cot/M3vBcSoISlKtTAOitQ9tmQ/public/build/target.snap.xdelta3.
Pushing target.snap.xdelta3 [ ] 0%
Pushing target.snap.xdelta3 [ ] 1%
Pushing target.snap.xdelta3 [ ] 2%
Pushing target.snap.xdelta3 [= ] 3%
Pushing target.snap.xdelta3 [= ] 4%
Pushing target.snap.xdelta3 [== ] 5%
Pushing target.snap.xdelta3 [== ] 6%
Pushing target.snap.xdelta3 [=== ] 7%
Pushing target.snap.xdelta3 [=== ] 8%
Pushing target.snap.xdelta3 [=== ] 9%
Pushing target.snap.xdelta3 [==== ] 10%
Pushing target.snap.xdelta3 [==== ] 11%
Pushing target.snap.xdelta3 [===== ] 12%
Pushing target.snap.xdelta3 [===== ] 13%
Pushing target.snap.xdelta3 [====== ] 14%
Pushing target.snap.xdelta3 [====== ] 15%
Pushing target.snap.xdelta3 [======= ] 16%
Pushing target.snap.xdelta3 [======= ] 17%
Pushing target.snap.xdelta3 [======= ] 18%
Pushing target.snap.xdelta3 [======== ] 19%
Pushing target.snap.xdelta3 [======== ] 20%
Pushing target.snap.xdelta3 [========= ] 21%
Pushing target.snap.xdelta3 [========= ] 22%
Pushing target.snap.xdelta3 [========== ] 23%
Pushing target.snap.xdelta3 [========== ] 24%
Pushing target.snap.xdelta3 [=========== ] 25%
Pushing target.snap.xdelta3 [=========== ] 26%
Pushing target.snap.xdelta3 [=========== ] 27%
Pushing target.snap.xdelta3 [============ ] 28%
Pushing target.snap.xdelta3 [============ ] 29%
Pushing target.snap.xdelta3 [============= ] 30%
Pushing target.snap.xdelta3 [============= ] 31%
Pushing target.snap.xdelta3 [============== ] 32%
Pushing target.snap.xdelta3 [============== ] 33%
Pushing target.snap.xdelta3 [=============== ] 34%
Pushing target.snap.xdelta3 [=============== ] 35%
Pushing target.snap.xdelta3 [=============== ] 36%
Pushing target.snap.xdelta3 [================ ] 37%
Pushing target.snap.xdelta3 [================ ] 38%
Pushing target.snap.xdelta3 [================= ] 39%
Pushing target.snap.xdelta3 [================= ] 40%
Pushing target.snap.xdelta3 [================== ] 41%
Pushing target.snap.xdelta3 [================== ] 42%
Pushing target.snap.xdelta3 [==========...

Read more...

Bug Watch Updater (bug-watch-updater)
Changed in firefox:
status: Confirmed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.