Peertube: activitypub-http-unicast speaks about other instance instead of itself

Created on 28 Sep 2018 · 13Comments · Source: Chocobozzz/PeerTube

PeerTube version or URL: v1.0.0-beta.15
URL can't be provided since they are on my private network :P There are three of them, and in this issue they will be identified as example1.com, example2.com & example3.com
Browser name/version: Google Chrome 69.0.3497.100
NodeJS version: v8.12.0
What is the expected behaviour?
Normally it should be

{
  "uri": "https://example1.com/inbox",
  "signatureActorId": 1,
  "body": {
    "type": "Update",
    "id": "https://example2.com/redundancy/videos/adec27df-05fd-4405-a98a-889764512d51/720-24/updates/2018-09-28T04:44:08.766Z",
    "actor": "https://example2.com/accounts/peertube",
    "object": {
      "id": "https://example2.com/redundancy/videos/adec27df-05fd-4405-a98a-889764512d51/720-24",
      "type": "CacheFile",
      "object": "https://example1.com/videos/watch/adec27df-05fd-4405-a98a-889764512d51",
      "expires": "2018-09-28T15:44:08.766Z",
      "url": {
        "type": "Link",
        "mimeType": "video/mp4",
        "href": "https://example2.com/static/webseed/adec27df-05fd-4405-a98a-889764512d51-720.mp4",
        "height": 720,
        "size": 238299178,
        "fps": 24
      },
      "to": [
        "https://example1.com/accounts/user1"
      ],
      "cc": [
        "https://example1.com/video-channels/channel1/followers",
        "https://example1.com/accounts/peertube/followers",
        "https://example1.com/accounts/user1/followers"
      ]
    },
    "to": [
      "https://example1.com/accounts/user1"
    ],
    "cc": [
      "https://example1.com/video-channels/channel1/followers",
      "https://example1.com/accounts/peertube/followers",
      "https://example1.com/accounts/user1/followers"
    ]
  }
}

What do you see instead?
However, after several "type": "Undo" like

{
  "uri": "https://example1.com/inbox",
  "signatureActorId": 1,
  "body": {
    "type": "Undo",
    "id": "https://example2.com/redundancy/videos/adec27df-05fd-4405-a98a-889764512d51/360-24/undo",
    "actor": "https://example2.com/accounts/peertube",
    "object": {
      "type": "Create",
      "id": "https://example2.com/redundancy/videos/adec27df-05fd-4405-a98a-889764512d51/360-24/activity",
      "actor": "https://example2.com/accounts/peertube",
      "object": {
        "id": "https://example2.com/redundancy/videos/adec27df-05fd-4405-a98a-889764512d51/360-24",
        "type": "CacheFile",
        "object": "https://example1.com/videos/watch/adec27df-05fd-4405-a98a-889764512d51",
        "expires": "2018-09-28T15:31:08.779Z",
        "url": {
          "type": "Link",
          "mimeType": "video/mp4",
          "href": "https://example2.com/static/webseed/adec27df-05fd-4405-a98a-889764512d51-360.mp4",
          "height": 360,
          "size": 88565156,
          "fps": 24
        },
        "to": [
          "https://www.w3.org/ns/activitystreams#Public"
        ],
        "cc": [
          "https://example2.com/accounts/peertube/followers"
        ]
      },
      "to": [
        "https://www.w3.org/ns/activitystreams#Public"
      ],
      "cc": [
        "https://example2.com/accounts/peertube/followers"
      ]
    },
    "to": [
      "https://example1.com/accounts/user1"
    ],
    "cc": [
      "https://example1.com/video-channels/channel1/followers",
      "https://example1.com/accounts/peertube/followers",
      "https://example1.com/accounts/user1/followers"
    ]
  }
}

Any "type": "Update" after that goes

{
  "uri": "https://example1.com/inbox",
  "signatureActorId": 1,
  "body": {
    "type": "Update",
    "id": "https://example3.com/redundancy/videos/adec27df-05fd-4405-a98a-889764512d51/1080-24/updates/2018-09-28T10:34:09.176Z",
    "actor": "https://example2.com/accounts/peertube",
    "object": {
      "id": "https://example3.com/redundancy/videos/adec27df-05fd-4405-a98a-889764512d51/1080-24",
      "type": "CacheFile",
      "object": "https://example1.com/videos/watch/adec27df-05fd-4405-a98a-889764512d51",
      "expires": "2018-09-30T10:34:09.176Z",
      "url": {
        "type": "Link",
        "mimeType": "video/mp4",
        "href": "https://example3.com/static/webseed/adec27df-05fd-4405-a98a-889764512d51-1080.mp4",
        "height": 1080,
        "size": 831372746,
        "fps": 24
      },
      "to": [
        "https://example1.com/accounts/user1"
      ],
      "cc": [
        "https://example1.com/video-channels/channel1/followers",
        "https://example1.com/accounts/peertube/followers",
        "https://example1.com/accounts/user1/followers"
      ]
    },
    "to": [
      "https://example1.com/accounts/user1"
    ],
    "cc": [
      "https://example1.com/video-channels/channel1/followers",
      "https://example1.com/accounts/peertube/followers",
      "https://example1.com/accounts/user1/followers"
    ]
  }
}

and journalctl goes

Sep 28 22:02:19 example2.com peertube[14047]: [example2.com:443] 2018-09-28 22:02:19.626 info: Running redundancy scheduler for strategy trending.
Sep 28 22:02:19 example2.com peertube[14047]: Executing (default): SELECT "VideoModel"."id", "VideoModel"."uuid", "VideoModel"."name", "VideoModel"."category", "VideoModel"."licence", "VideoModel"."language", "VideoModel"."privacy", "VideoModel"."nsfw", "VideoModel"."description", "VideoModel"."support", "VideoModel"."duration", "VideoModel"."views", "VideoModel"."likes", "VideoModel"."dislikes", "VideoModel"."remote", "VideoModel"."url", "VideoModel"."commentsEnabled", "VideoModel"."waitTranscoding", "VideoModel"."state", "VideoModel"."publishedAt", "VideoModel"."channelId", "VideoModel"."createdAt", "VideoModel"."updatedAt", "VideoFiles"."id" AS "VideoFiles.id", "VideoFiles"."resolution" AS "VideoFiles.resolution", "VideoFiles"."size" AS "VideoFiles.size", "VideoFiles"."extname" AS "VideoFiles.extname", "VideoFiles"."infoHash" AS "VideoFiles.infoHash", "VideoFiles"."fps" AS "VideoFiles.fps", "VideoFiles"."videoId" AS "VideoFiles.videoId", "VideoFiles"."createdAt" AS "VideoFiles.createdAt", "VideoFiles"."updatedAt" AS "VideoFiles.updatedAt", "VideoFiles->RedundancyVideos"."id" AS "VideoFiles.RedundancyVideos.id", "VideoFiles->RedundancyVideos"."fileUrl" AS "VideoFiles.RedundancyVideos.fileUrl" FROM "video" AS "VideoModel" LEFT OUTER JOIN "videoFile" AS "VideoFiles" ON "VideoModel"."id" = "VideoFiles"."videoId" LEFT OUTER JOIN "videoRedundancy" AS "VideoFiles->RedundancyVideos" ON "VideoFiles"."id" = "VideoFiles->RedundancyVideos"."videoFileId" WHERE "VideoModel"."id" = 12;
Sep 28 22:02:19 example2.com peertube[14047]: [example2.com:443] 2018-09-28 22:02:19.669 info: Will duplicate video https://example1.com/videos/watch/980531ad-9e4f-4ab2-b08b-218ebbcafd35 in redundancy scheduler "trending".
Sep 28 22:02:19 example2.com peertube[14047]: [example2.com:443] 2018-09-28 22:02:19.676 info: Extending expiration of https://example3.com/redundancy/videos/980531ad-9e4f-4ab2-b08b-218ebbcafd35/720-24.
Sep 28 22:02:19 example2.com peertube[14047]: [example2.com:443] 2018-09-28 22:02:19.682 info: Creating job to update cache file https://example3.com/redundancy/videos/980531ad-9e4f-4ab2-b08b-218ebbcafd35/720-24.
Sep 28 22:02:19 example2.com peertube[14047]: [example2.com:443] 2018-09-28 22:02:19.720 info: Processing ActivityPub unicast in job 711.
Sep 28 22:02:19 example2.com peertube[14047]: [example2.com:443] 2018-09-28 22:02:19.724 info: Extending expiration of https://example3.com/redundancy/videos/980531ad-9e4f-4ab2-b08b-218ebbcafd35/1076-24.
Sep 28 22:02:19 example2.com peertube[14047]: [example2.com:443] 2018-09-28 22:02:19.745 info: Creating job to update cache file https://example3.com/redundancy/videos/980531ad-9e4f-4ab2-b08b-218ebbcafd35/1076-24.
Sep 28 22:02:19 example2.com peertube[14047]: [example2.com:443] 2018-09-28 22:02:19.779 info: Running redundancy scheduler for strategy recently-added.
Sep 28 22:02:19 example2.com peertube[14047]: [example2.com:443] 2018-09-28 22:02:19.785 info: Processing ActivityPub unicast in job 712.

Additional information: all logs above are from example2.com; all videos are published on example1.com, both example2.com & example3.com follows only example1.com with video redundancy enabled. Affected videos can only be webseeded from example1.com and example3.com, no related video files are found on example2.com

Browser console log if useful: Not-relavant I suppose?
Server log if useful (journalctl or /var/www/peertube/storage/logs):
See above

Type

Source

SerCom-KC

All 13 comments

example2.com are still sending "type": "Update"s to example1.com even after affected videos on example1.com (original upload instance) are deleted

SerCom-KC on 29 Sep 2018

I think I found a way to reproduce this issue (and maybe the possible cause?):

Let example2.com & example3.com follow example1.com, and their redundancy check_interval to 1 minutes;
Publish a new video on example1.com, ideally a lengthy one which takes time to download the full video;
Both example2.com & example3.com should start the redundancy process; however, example3.com completes the process FIRST while example2.com stucks for some reason;
example3.com sends an AP unicast to example1.com which forwards it to example2.com (~~indicating that it has finished the redundancy process?~~ while example2.com still stucks on the redundancy process - I guess this is the point);
~~Since example2.com stucks,~~ Interrupt example2.com's redundancy process by restarting its PeerTube service;

Currently I have to delete invalid records in the videoRedundancy table manually (sudo -u postgres psql -d peertube_prod -c 'DELETE FROM "videoRedundancy" WHERE "fileUrl" !~ '"'"'example2'"'"';') ~~and then disallow access to /inbox between example2.com & example3.com~~ as a temporary workaround.

EDIT: Looks like /inbox & restarting isn't the cause.
EDIT 2: Confirmed this issue can be reproduced on example3.com if example2.com completes the redundancy process FIRST.
EDIT 3: Add workaround command

SerCom-KC on 29 Sep 2018

Another problem is that instance will still tries to duplicate a deleted (on the origin instance) video which might blocks the redundancy process with impossible jobs. UUID of deleted videos are still present in video table of follower-instances, don't know why but I'm pretty sure the AP deletion message has received correctly

SerCom-KC on 30 Sep 2018

facepalm

Thank you very much @SerCom-KC for this detailed issue. I think this should be fixed by https://github.com/Chocobozzz/PeerTube/commit/46f8d69b4e58a3006c32b2e0d97b9262fd30fd6b, but I keep this issue opened so that you can confirm.

Chocobozzz on 1 Oct 2018

😄1

@Chocobozzz Sure, will definitely test on beta 16 once it gets released.
What about the second issue? Don't know what's the expected behavior on follower-instances when a video on the origin instance gets deleted, but it's probably a good idea to check before duplicating in case the follower-instance didn't receive the AP deletion broadcast

SerCom-KC on 1 Oct 2018

The video should be deleted, but if you stopped your instance maybe the message was not received. It's not really important, the redundancy scheduler will just timeout, and the video will be deleted after some time.

But to speed up the eviction, I forced the refresh process in https://github.com/Chocobozzz/PeerTube/commit/26649b4215ac68eed5601d9412d2d7ddee98b543

If you will test beta 16, I'm closing this issue. Do not hesitate to comment when we'll release it.

Chocobozzz on 1 Oct 2018

👍1

Hmm... now both follower-instances say

error: Cannot run videos redundancy trending. {
   "meta": {
     "err": {
       "stack": "TypeError: Cannot read property 'Account' of undefined\n    at VideoModel.getBaseUrls (/var/www/peertube/versions/peertube-v1.0.0-beta.16/dist/server/models/video/video.js:698:89)\n    at VideosRedundancyScheduler.<anonymous> (/var/www/peertube/versions/peertube-v1.0.0-beta.16/dist/server/lib/schedulers/videos-redundancy-scheduler.js:127:58)\n    at Generator.next (<anonymous>)\n    at fulfilled (/var/www/peertube/versions/peertube-v1.0.0-beta.16/dist/server/lib/schedulers/videos-redundancy-scheduler.js:4:58)\n    at <anonymous>",
       "message": "Cannot read property 'Account' of undefined"
     }
   }
}

SerCom-KC on 1 Oct 2018

@SerCom-KC Fixed in https://github.com/Chocobozzz/PeerTube/commit/99cc653f47a5db664ec119e66a84c8f6454eed0b

Chocobozzz on 1 Oct 2018

For some reason activitypub-http-unicast jobs are no longer showed up in completed job list after a

Error: ESOCKETTIMEDOUT
    at ClientRequest.<anonymous> (/var/www/peertube/versions/peertube-v1.0.0-rc.2/node_modules/request/request.js:816:19)
    at Object.onceWrapper (events.js:313:30)
    at emitNone (events.js:106:13)
    at ClientRequest.emit (events.js:208:7)
    at TLSSocket.emitTimeout (_http_client.js:707:34)
    at Object.onceWrapper (events.js:313:30)
    at emitNone (events.js:106:13)
    at TLSSocket.emit (events.js:208:7)
    at TLSSocket.Socket._onTimeout (net.js:422:8)
    at ontimeout (timers.js:498:11)
    at tryOnTimeout (timers.js:323:5)
    at Timer.listOnTimeout (timers.js:290:5)

Tested with v1.0.0-rc2

SerCom-KC on 6 Oct 2018

@SerCom-KC Because there was an error, they should appear on the delayed or failed state

Chocobozzz on 8 Oct 2018

Well the actual situation is one of the cache instance did send the unicast and the origin instance did receive & forward it, but it didn't go into origin instance's database.
I'll go on and check the origin's database.

Also a 404 check when extending the cache time might be necessary, wondering why neither of my instances process the deletion at first

EDIT: Looks like the problematic cache instance gets a lot of bad actor follow scores on the origin

SerCom-KC on 10 Oct 2018

Also a 404 check when extending the cache time might be necessary,

We added it after the rc2 :) https://github.com/Chocobozzz/PeerTube/commit/be691a57c590348fd36d6e11dc1fe4cc8eaa0719

Chocobozzz on 10 Oct 2018

After several days of investigation I believe there's a signature verification (or something similar) process when the origin instance receives the redundancy extension message. Redundancy creation does not seem to trigger the verification.
Haven't check the code to confirm it, so I'd like to ask here to see if I'm wrong.

I did a complete database reset on both cache instances before (so there's a key pair change), but never on origin instance (so the public key in db is still the old one)
And, since both cache instances does not follow each other directly, they'll need to wait for the forwarded message from the origin instance to know about other instance's redundancy status.
As a result, both cache instances have the correct redundancy info, while the origin instance falls behind after the first expiry (it only forwards the redundancy extension message, but not accepting it into db)

SerCom-KC on 19 Oct 2018

Was this page helpful?

0 / 5 - 0 ratings