Wordpress-ios: Editor: multiple posts being uploaded as duplicates on Jetpack sites

[designsimply]

We've received at least 3 reports so far similar to the following and we need help troubleshooting and tracking these cases to look for trends or to find the reason why the app keeps going with publishing retries after at least one successful publish goes through.

Each time I create a post it published several times therefore making a mess of my social media outlets. I have to scramble to delete and keep checking each site because I never l know how many times it will keep re-publishing.

This happens every time from the app and the desktop even under stable internet connection. All I do is click publish and within minutes the post republished itself two or three more times.

• Type of site: Jetpack Premium
• WPiOS 14.8.2
• iPhone XS (iPhone11,2)
• iOS 13.4.1

^{(internal references: 3010797-zen p4a5px-2yY-p2 h/t @rezzap)}

Sample snippet from a random editor session from the app logs from this user:

2020-05-26 19:12:44:127 🔵 Tracked: editor_post_created <blog_id: 140620730, post_type: post, tap_source: tab_bar>
2020-05-26 19:12:44:810 🔵 Tracked: editor_session_start <blog_type: jetpack, content_type: new, editor: gutenberg, has_unsupported_blocks: 0, post_type: post, session_id: F3AD3103-2172-4625-9FFF-DA212EC80567, startup_time_ms: 625, unsupported_blocks: (
)>
2020-05-26 19:12:53:382 TracksService sendQueuedEvents completed. Sent 5 events.
2020-05-26 19:17:05:899 <PostSettingsViewController: 0x10b852000> viewDidLoad
2020-05-26 19:17:05:912 🔵 Tracked: post_settings_shown <>
2020-05-26 19:17:08:743 TracksService sendQueuedEvents completed. Sent 1 events.
2020-05-26 19:17:12:598 🔵 Tracked: editor_post_featured_image_changed <action: added, via: settings>
2020-05-26 19:17:12:805 🔵 Tracked: media_service_upload_started <blog_id: 140620730>
2020-05-26 19:17:22:143 🔵 Tracked: media_service_upload_successful <blog_id: 140620730>
2020-05-26 19:17:23:923 TracksService sendQueuedEvents completed. Sent 3 events.
2020-05-26 19:17:28:481 🔵 Tracked: editor_post_category_changed <via: settings>
2020-05-26 19:17:29:249 🔵 Tracked: editor_post_category_changed <via: settings>
2020-05-26 19:17:30:248 🔵 Tracked: editor_post_category_changed <via: settings>
2020-05-26 19:17:32:740 🔵 Tracked: post_settings_add_tags_shown <>
2020-05-26 19:17:39:161 TracksService sendQueuedEvents completed. Sent 4 events.
2020-05-26 19:18:49:996 🔵 Tracked: editor_post_tags_added <via: settings>
2020-05-26 19:18:55:805 TracksService sendQueuedEvents completed. Sent 1 events.
2020-05-26 19:19:06:717 🔵 Tracked: editor_photo_added <blog_id: 140620730, bytes: 101065728, ext: jpeg, media_origin: not_identified, megapixels: 1, mime: image/jpeg, via: local_library>
2020-05-26 19:19:06:731 🔵 Tracked: media_service_upload_started <blog_id: 140620730>
2020-05-26 19:19:11:002 TracksService sendQueuedEvents completed. Sent 2 events.
2020-05-26 19:19:13:473 🔵 Tracked: media_service_upload_successful <blog_id: 140620730>
2020-05-26 19:19:27:054 TracksService sendQueuedEvents completed. Sent 1 events.
2020-05-26 19:20:34:612 <PostSettingsViewController: 0x10b85cc00> viewDidLoad
2020-05-26 19:20:34:615 🔵 Tracked: post_settings_shown <>
2020-05-26 19:20:42:359 TracksService sendQueuedEvents completed. Sent 1 events.
2020-05-26 19:21:09:530 <WordPress.WordPressAppDelegate: 0x28093fc80> applicationWillResignActive(_:)
2020-05-26 19:21:09:734 Stats Period: finished persisting Period Stats to disk.
2020-05-26 19:21:10:016 <WordPress.WordPressAppDelegate: 0x28093fc80> applicationDidBecomeActive(_:)
2020-05-26 19:21:10:019 checkAppleIDCredentialState: No Apple ID found.
2020-05-26 19:21:31:002 <WordPress.WordPressAppDelegate: 0x28093fc80> applicationWillResignActive(_:)
2020-05-26 19:21:31:082 Stats Period: finished persisting Period Stats to disk.
2020-05-26 19:21:31:890 <WordPress.WordPressAppDelegate: 0x28093fc80> applicationDidEnterBackground(_:)
2020-05-26 19:21:31:901 🔵 Tracked: application_closed <last_visible_screen: Post Editor, time_in_app: 534>

Then later in the same set of logs…

2020-05-26 19:24:45:698 🔵 Tracked: application_closed <last_visible_screen: Blog List, time_in_app: 123>
2020-05-26 19:24:45:712 PingHub disconnecting
2020-05-26 19:24:45:951 PingHub disconnected: WSError(type: Starscream.ErrorType.protocolError, message: "", code: 1000)
2020-05-26 19:40:54:746 <WordPress.WordPressAppDelegate: 0x28093fc80> applicationWillEnterForeground(_:)
2020-05-26 19:40:54:752 PingHub connecting
2020-05-26 19:40:55:051 Stats Period: finished persisting Period Stats to disk.
2020-05-26 19:40:55:119 Stats Period: Finished loading Period data from Core Data.
2020-05-26 19:40:55:124 Stats Period: Finished setting data to Period store from Core Data.
2020-05-26 19:40:55:214 🔵 Tracked: auto_upload_post_invoked <post_status: publish, upload_action: upload>

The auto_upload_post_invoked looks suspicious to me in this context, but the logs don't say which post that was invoked for so I can't tell for sure if it's the same one from the previous log snippet. You can find the full set of app logs for that session in the sidebar in 3010797-zen.

[designsimply]

I labeled this high priority because, based on our priority matrix, severity is critical due to unexpected publishing and impact is medium because we've only noted 2-4 user reports so far. Noting that if more user reports come in then we will raise priority to critical.

^{(internal reference: paaHJt-UE-p2)}

[designsimply]

Also see https://android.forums.wordpress.org/topic/wordpress-app-can-not-upload-my-posts-anymore.

[designsimply]

Because it has been a few weeks since this issue was raised and there have been no new reports from users here on this issue and no replies from users on the support requests noted so far, I'm lowering priority to medium with an ask to please ping me right away if this comes up again. I think it sounds like a terrible problem and would like to help resolve the issue or direct users to where they can get help if it's not something we can control from the app side!

For any future reports, it would help to know:

• app version if it happened while using mobile
• type of site (always Jetpack?)
• WP version if it happened on a Jetpack site
• list of active plugins (especially any social-media-related)
• hosting provider (in case it's limited to one in particular—unlikely but might be worth a check)

[rezzap]

Another report of this happening:

• app version: 15.6
• Jetpack connected site
• WordPress: 5.5.1
• Plugins: WooCommerce PayPal Checkout Gateway, WooCommerce, UpdraftPlus - Backup/Restore, Bluehost
• Bluehost site

Reported in 3333432-zen

had done nothing to my site for months when all of a sudden this happened.

I only post once a day. I just posted today's post. I got the error message. I am attaching a screenshot. I will check back to see if it proceeds to post it anyway which is what has been happening...it posts it multiple times after saying it could not post as the attached image shows.

I have done my posts both on cellular data, home wifi, and wifi at gym. Data quality doesn't seem to be an issue. This issue only recently started. I have been doing the same post of 300-400 words for almost 2 years.

They initially had the Sample API time-out error in the debugger as the other sites reported have had, but after disabling plugins this is showing 200 response.

App logs for this user's initial report from 2020-09-20 with tokens/site names removed

WordPress - 15.6 - Version code: 915
Android device name: Samsung SM-N950U

01 - [Sep-20 16:16 UTILS] SnackbarSequencer > prepareSnackBar message [1 file not uploaded
There was an error uploading this post: We couldn't complete this action, and didn't publish this post..]
02 - [Sep-20 16:16 UTILS] SnackbarSequencer > before delay
03 - [Sep-20 16:16 API] WhatsNewStore: fetchWhatsNew
04 - [Sep-20 16:16 API] Dispatching action: AccountAction-FETCHED_ACCOUNT
05 - [Sep-20 16:16 UTILS] SnackbarSequencer > after delay
06 - [Sep-20 16:16 UTILS] SnackbarSequencer > item removed from the queue
07 - [Sep-20 16:16 UTILS] SnackbarSequencer > finishing start()
08 - [Sep-20 16:16 UTILS] App goes to background
09 - [Sep-20 16:16 STATS] 🔵 Tracked: application_closed, Properties: {"time_in_main_reader":0,"last_visible_screen":"My Site","time_in_reader_paged_post":0,"time_in_app":71,"time_in_subfiltered_list":0,"time_in_reader_filtered_list":0}
10 - [Sep-20 16:16 MAIN] ConnectionChangeReceiver successfully unregistered
11 - [Sep-20 16:18 STATS] 🔵 Tracked: deep_link_not_default_handler, Properties: {"interceptor_classname":"org.wordpress.android.ui.reader.ReaderPostPagerActivity"}
12 - [Sep-20 16:18 UTILS] App comes from background
13 - [Sep-20 16:18 STATS] 🔵 Tracked: application_opened
14 - [Sep-20 16:18 READER] notifications update job service > job scheduled
15 - [Sep-20 16:18 UTILS] trackLastActivity, activityId: My Site
16 - [Sep-20 16:18 POSTS] PageStore: getPagesWithLocalChanges
17 - [Sep-20 16:18 API] Dispatching action: AccountAction-FETCH_ACCOUNT
18 - [Sep-20 16:18 API] Dispatching action: SiteAction-FETCH_POST_FORMATS
19 - [Sep-20 16:18 API] Dispatching action: SiteAction-FETCH_SITE_EDITORS
20 - [Sep-20 16:18 API] WhatsNewStore: fetchWhatsNew
21 - [Sep-20 16:18 NOTIFS] notifications update job service > created
22 - [Sep-20 16:18 API] WhatsNewStore: fetchWhatsNew
23 - [Sep-20 16:18 NOTIFS] Sending GCM token to our remote services: *** REDACTED ***
24 - [Sep-20 16:18 SUPPORT] Zendesk push notifications successfully enabled!
25 - [Sep-20 16:18 UTILS] Remote config updated: false
26 - [Sep-20 16:18 API] Received Jetpack Monitor module options
27 - [Sep-20 16:18 NOTIFS] Register token action succeeded
28 - [Sep-20 16:18 NOTIFS] Server response OK. The device_id: 26233540
29 - [Sep-20 16:18 API] Dispatching action: AccountAction-FETCHED_ACCOUNT
30 - [Sep-20 16:18 API] Dispatching action: SiteAction-FETCHED_SITE_EDITORS
31 - [Sep-20 16:18 DB] Site found by (local) ID: 1
32 - [Sep-20 16:18 DB] Updating site: *** REDACTED ***
33 - [Sep-20 16:18 NOTIFS] notifications update service > completed
34 - [Sep-20 16:18 NOTIFS] notifications update job service > all tasks completed
35 - [Sep-20 16:18 NOTIFS] notifications update job service > destroyed
36 - [Sep-20 16:18 STATS] 🔵 Tracked: notification_tapped_segmented_control, Properties: {"selected_filter":"all"}
37 - [Sep-20 16:18 READER] notifications update job service > job scheduled
38 - [Sep-20 16:18 UTILS] trackLastActivity, activityId: Notifications
39 - [Sep-20 16:18 STATS] 🔵 Tracked: notifications_accessed
40 - [Sep-20 16:18 READER] notifications update job service > job scheduled
41 - [Sep-20 16:18 NOTIFS] notifications update job service > created
42 - [Sep-20 16:18 NOTIFS] notifications update job service > destroyed
43 - [Sep-20 16:18 NOTIFS] notifications update job service > created
44 - [Sep-20 16:18 API] Received Jetpack settings response
45 - [Sep-20 16:18 API] Received Jetpack module settings
46 - [Sep-20 16:18 NOTIFS] notifications update service > completed
47 - [Sep-20 16:18 NOTIFS] notifications update job service > all tasks completed
48 - [Sep-20 16:18 NOTIFS] notifications update job service > destroyed
49 - [Sep-20 16:18 API] Received response to Settings REST request.
50 - [Sep-20 16:18 API] Dispatching action: SiteAction-FETCHED_POST_FORMATS
51 - [Sep-20 16:18 SETTINGS] Post formats successfully fetched!
52 - [Sep-20 16:18 API] Received site Categories
53 - [Sep-20 16:18 API] Successfully fetched WP.com categories
54 - [Sep-20 16:18 STATS] 🔵 Tracked: notification_settings_list_opened
55 - [Sep-20 16:18 NOTIFS] Get settings action succeeded
56 - [Sep-20 16:18 UTILS] trackLastActivity, activityId: Notifications
57 - [Sep-20 16:18 API] Dispatching action: AccountAction-FETCH_ACCOUNT
58 - [Sep-20 16:18 READER] notifications update job service > job scheduled
59 - [Sep-20 16:18 READER] notifications update job service > job scheduled
60 - [Sep-20 16:18 API] WhatsNewStore: fetchWhatsNew
61 - [Sep-20 16:18 NOTIFS] notifications update job service > created
62 - [Sep-20 16:18 NOTIFS] notifications update job service > destroyed
63 - [Sep-20 16:18 NOTIFS] notifications update job service > created
64 - [Sep-20 16:18 API] Dispatching action: AccountAction-FETCHED_ACCOUNT
65 - [Sep-20 16:18 NOTIFS] notifications update service > completed
66 - [Sep-20 16:18 NOTIFS] notifications update job service > all tasks completed
67 - [Sep-20 16:18 NOTIFS] notifications update job service > destroyed
68 - [Sep-20 16:18 UTILS] trackLastActivity, activityId: My Site
69 - [Sep-20 16:18 STATS] 🔵 Tracked: my_site_tab_accessed, Properties: {"blog_id":151294194,"is_jetpack":true}
70 - [Sep-20 16:18 STATS] 🔵 Tracked: site_menu_opened, Properties: {"blog_id":151294194,"is_jetpack":true,"menu_item":"site_settings"}
71 - [Sep-20 16:18 STATS] 🔵 Tracked: site_settings_accessed, Properties: {"blog_id":151294194,"is_jetpack":true}
72 - [Sep-20 16:18 API] Dispatching action: SiteAction-FETCH_POST_FORMATS
73 - [Sep-20 16:18 API] Dispatching action: SiteAction-FETCH_SITE_EDITORS
74 - [Sep-20 16:18 API] Received Jetpack Monitor module options
75 - [Sep-20 16:18 API] Dispatching action: SiteAction-FETCHED_SITE_EDITORS
76 - [Sep-20 16:18 DB] Site found by (local) ID: 1
77 - [Sep-20 16:18 DB] Updating site: *** REDACTED ***
78 - [Sep-20 16:18 API] Received response to Settings REST request.
79 - [Sep-20 16:18 API] Received Jetpack settings response
80 - [Sep-20 16:18 API] Received site Categories
81 - [Sep-20 16:18 API] Successfully fetched WP.com categories
82 - [Sep-20 16:18 API] Received Jetpack module settings
83 - [Sep-20 16:18 API] Dispatching action: SiteAction-FETCHED_POST_FORMATS
84 - [Sep-20 16:18 SETTINGS] Post formats successfully fetched!
85 - [Sep-20 16:18 SETTINGS] Post formats successfully fetched!
86 - [Sep-20 16:18 STATS] 🔵 Tracked: site_settings_more_settings_accessed, Properties: {"blog_id":151294194,"is_jetpack":true}
87 - [Sep-20 16:19 API] Dispatching action: SiteAction-UPDATE_SITE
88 - [Sep-20 16:19 DB] Site found by (local) ID: 1
89 - [Sep-20 16:19 DB] Updating site: *** REDACTED ***
90 - [Sep-20 16:19 UTILS] trackLastActivity, activityId: My Site
91 - [Sep-20 16:19 API] Dispatching action: AccountAction-FETCH_ACCOUNT
92 - [Sep-20 16:19 API] WhatsNewStore: fetchWhatsNew
93 - [Sep-20 16:19 API] Dispatching action: AccountAction-FETCHED_ACCOUNT
94 - [Sep-20 16:19 STATS] 🔵 Tracked: me_tab_accessed
95 - [Sep-20 16:19 STATS] 🔵 Tracked: support_opened, Properties: {"origin":"ME_SCREEN_HELP"}
96 - [Sep-20 16:19 UTILS] trackLastActivity, activityId: Help Screen
97 - [Sep-20 16:19 STATS] 🔵 Tracked: support_help_center_viewed
98 - [Sep-20 16:20 UTILS] trackLastActivity, activityId: Help Screen
99 - [Sep-20 16:20 STATS] 🔵 Tracked: support_new_request_viewed

[erricgunawan]

An update from 3333432-zen:

User disabled their 4 plugins and the result:

Yes, last night, my post uploaded quickly and with no errors.

They activated UpdraftPlus and the result was:

I posted again today, and this time I got the error message. It subsequently posted twice without my responding in any way to the error notice.
...
This plugin was not on my account when this issue started. So, I think it is not related to the issue...

They then deactivate UpdraftPlus and activate Bluehost (along with Jetpack), the result was:

Today's post also got the error and with no response from me to the error immediately posted twice.
The only 2 plugins active for this are Blue Host and Jet Pack.
The error is showing me that the plugins have nothing to do with the error.

They will continue with disabling Bluehost and activating WooCommerce. They'll report the result after that.

[rezzap]

The user from 3333432-zen just confirmed there was no issue today when they published with WooCommerce active.

@designsimply I just wanted to make sure this was on your radar since we've got some good new updates here.

[designsimply]

Thanks for the extra ping @rezzap! It sounds like this issue is happening to Bluehost+Jetpack users only and it would be good to keep posting any new cases at all that we can find and also, if possible, if we can get app logs from _right after_ the problem happens that may also help us. We can also try testing from a Bluehost test site when timing allows.

[aerych]

I've been looking into this issue and I want to share what I'm seeing from my pov:

Incident review

I started by reviewing the reports we've received. There seems to be a total of five individuals reporting, one uses the iOS app the others the Android app.

Android

1. One report in the WPAndroid forums. - "Forum"
2. 2972469-zen - "Soccer"
3. 3333432-zen - "Mirror"
4. 3080931-zen - "Edit"

iOS

1. 3010797-zen - "Yel". "Yel" has reached out several times to both mobile and Jetpack support (see their related tickets), and who has mentioned the duplication also happens(?) publishing from the desktop.

The only factor common to each case is Jetpack was installed, and that they were seeing duplicate posts on their sites.

Analysis

We have the most information from "Yel" an "Mirror". Both report seeing errors in the app when publishing, and that duplicates appear without them interacting with the error message.
"Mirror" has troubleshooted by disabling plugins to see if one (or more) are triggering the issue. Some headway may have been made.
"Yel" has shared screenshots that show the duplicated posts appearing in the Published list _and_ under the Drafts list. Troubleshooting attempts have been unsuccessful.
"Soccer" and "Edit" provide little to go on beyond the initial report. "Forum" is the only one who reports "100s" of duplicates and is an interesting outlier.
It is perhaps worth noting that none of our Android user's reported duplication when publishing from a browser.

Causal theory

There are a few touch points we can look at for the cause of the duplication:

• Both iOS and Android app's have mechanisms for handling offline publishing attempts and for auto uploading when coming back online. These mechanism are obvious places to look for the cause, particularly if they follow similar logic.
• Since Jetpack is being used, the WordPress.com REST API should be what both apps are using to publish, which, in turn, should be forwarding the API calls to the user's site. The mechanism that forwards requests and responses would be a place to look.
• Next, we have the user's site which ultimately must handle and respond to the API calls made by the app and proxied through the WPCom REST API.
• Lastly, and perhaps the least likely, we have quirks with the physical devices being used.

Are we overlooking anything?

I think we can rule out a glitch in the app code, or in the wpcom/Jetpack code being _individually_ responsible for the issue. My rationale is that if either of these were the case, we should see orders of magnitude more reports than the five we have. I also think we can rule out hardware glitches since shouldn't see so many similar reports and that doesn't account for our iOS user reproducing dups from the desktop.
This leaves the site itself, or a combination of multiple factors.
I'm thinking it's most likely we have a combination of factors between the site and the app, and this is mostly due to the screen shots shared by our iOS user, "Yel".

The case of "Yel"

Recall that the screen shots shared by "Yel" showed duplicate posts in both the Published and Drafts lists. A couple of scenarios occur to me that might explain this from the app's perspective.

First, suppose the app attempts to publish a local draft with no post ID. The post is published successfully, but the server returns an error (or mangled response the app would interpret as an error). There is now a draft (still with no post ID), and a remote post. In this scenario more duplicates can be created as publishing is retried. We've encountered cases where malformed responses (particularly with XML-RPC) created problems with the apps in the past so I think this is within the realm of possibilities.

Second, suppose that the app's background process that handles auto uploading is interrupted after the request to publish a draft is sent, and before the response is received. Perhaps the interruption is due to lost connectivity, or maybe the app is terminated. This will be interpreted as a failure status and the publish attempt would be retried later. This seems rather unlikely in this case simply because how consistently the issue is affecting "Yel".

iOS Code audit

I spent some time auditing the iOS publishing code, particularly the upload coordinators, and performing offline/online publishing tests. I experienced a few issues due to the quality of the network I was testing with, and a known issue with Gutenberg taking _forever_ to load when developing, but happily the app successfully published as expected with no dups in my test cases. There is a lot of code at play, but from my read and tests there was nothing obvious that would contribute to the issue our user was seeing. And, again, if there were we'd expect to hear more reports, on iOS in particular.

A final thought about the desktop report

I'm curious about the report the duplication also happens on the desktop by our iOS user. If this is the case then the issue is 100% outside of the app, and potentially unrelated to Jetpack if publishing was not occurring via calypso.
That said, because the iOS app's auto publish behavior can retry in the background, I would want to rule out the scenario where the app was still attempting to publish when our user went to the desktop to publish a non-local draft that was having errors in the app, and just happened to look like desktop publishing was also causing dups.

Take aways

In the case of "Yel" I'm inclined to chalk this up to something particular to our user's site and outside our ability to control, or that needs to be addressed in the iOS app.

In the case of our Android users, I haven't done a deep dive into the Android code (and there are others who would do a better job) so I won't say there _couldn't_ be an in-app cause. But, at least in the case of "Mirror" the issue is potentially due to a combination of plugins (pending further reports).