cdmdotnet / Manatee.Trello

A fully object-oriented .Net wrapper for Trello's RESTful API written in C#.
MIT License
121 stars 43 forks source link

Card description is replaced by template card description after changing it #309

Open agross opened 5 years ago

agross commented 5 years ago

Describe the bug The card description (main text) is replaced by the template card description shortly after setting a custom description.

To Reproduce I don't know a way to exactly reproduce the error, but it has been reported more than once by our users. It affects a certain kind of card for us, but so far I do not know what makes it special.

The basic process is as follows:

  1. Copy card from a template (which also has a description)
  2. Set name, description and position
  3. Upload an attachment
  4. Set custom fields

Expected behavior The description set in step 2 stays.

Desktop (please complete the following information):

Additional context

To debug this issue further, is there a way to force a flush of in-memory card data to the Trello API or to force a re-read from the Trello API?

gregsdennis commented 5 years ago

To force a refresh, you can pass a true into the .Refresh() call.

To flush the data, you can call TrelloProcessor.Flush().

For more in-depth logging, I'd suggest you provide an ILog implementation into the configuration. Just about everything is logged as debug, so you can capture it there.

agross commented 5 years ago

I made some changes to our code based on your suggestions.

@@ -53,6 +53,8 @@ public async Task Handle(ErfasseInTrello message, IMessageHandlerContext context
       card.Description = message.Description;
       card.Position = Position.Top;

+      await card.Refresh(true);
+
       var tasks = message.Attachments?
                          .ToList()
                          .Select(x => card.Attachments.Add(x.BinaryData, x.Name));
@@ -62,6 +64,13 @@ public async Task Handle(ErfasseInTrello message, IMessageHandlerContext context
       }

       await MapFields(message, board, card);
+
+      await TrelloProcessor.Flush();
+
+      await card.Refresh(true);
+
+      System.Diagnostics.Trace.Assert(card.Description == message.Description,
+                                      "Card message should be the one that was set");
     }

     async Task MapFields(ErfasseInTrello message, IBoard board, ICard card)

Because we process a lot of cards I didn't include the logging yet. It would have been better because today we got another one of those cards where the description remains the one from the template.

A user described that he was looking at the card with the correct description, but the description was replaced automatically after he left the card open. This is super strange, like a rollback happening in the background (on behalf of Trello?).

Unfortunately, changes to the card description are not logged in the card's Activity section. What is logged that our code calling out to Manatee.Trello runs to completion because custom fields were set (and remain) via MapFields and the Trace.Assert doesn't fail.

agross commented 5 years ago

For more in-depth logging, I'd suggest you provide an ILog implementation into the configuration.

We saw another one of those cards created yesterday. I made some annotations and removed sensitive stuff.

As you can see at the end of the log, Trello returns TEMPLATE DESCRIPTION instead of NEW CARD DESCRIPTION for the refreshed card.

log.txt

gregsdennis commented 5 years ago

Looking at the last content in the log, there are two interesting elements:

{
  "id":"5da983a3f7550a0e7228bcc0",
  ...
  "desc": "... TEMPLATE DESCRIPTION ...",
  "actions": [
    { ... },
    { ... },
    { ... },
    {
      "id": "5da983a415d33a091eedcf60",
      "idMemberCreator": "565d6f76542ab21fa642c4e7",
      "data": {
        "old": {"desc": "... TEMPLATE DESCRIPTION ..."},
        "card": {
          "desc": "... NEW CARD DESCRIPTION ...",
          "id": "5da983a3f7550a0e7228bcc0",
          ...
        },
        ...
      },
      ...
    },
    ...
  ],
  ...
}

What strikes me as odd is that it contains the action where you changed the description, but the primary data for the card clearly still has the old description (I agree with your assessment).

I can raise this to Trello as perhaps a race condition, but I think that my library is interpreting this response as it should. It won't overwrite cached objects with data received inside actions because those are generally historical snapshots rather than current values.

gregsdennis commented 5 years ago

Filed issue with Trello: https://community.developer.atlassian.com/t/eventually-consistency-maybe/32827?u=gregsdennis

agross commented 5 years ago

Filed issue

Thank you!

bentleycook commented 5 years ago

@agross When you say template card do you mean a random card that you are using as a template in that you regularly make copies of it? Can you share your API key?

@gregsdennis Can you walk me through the individual HTTP requests the library is making for this? Is it doing a POST and then following up with PUTs? And for each call, which fields are being included?

gregsdennis commented 5 years ago

Hm... you know what, @bentleycook, I think this may be a different issue. It doesn't look like the name/description update is going out.

(Looking at the log file without wrapping text helped.)

Lines of note from the log:


The attachment and custom field updates happen immediately because they're separate API calls, and I can't combine them with anything else. But in an effort to save on API calls, I wait for property setting (e.g. name and description) to pause for a bit before sending an update. To accommodate this potentially occurring at the end of life for the running thread, I created the TrelloProcessor.Flush() method which should trigger a "last call" of sorts that immediately uploads all pending updates and waits for them to complete.

It doesn't look like the update is happening... sometimes. There may be a timing issue where the normal timed trigger goes off, and the "last call" trigger doesn't capture the pending change. Then the thread ends before the update can go out.


That said, it's still odd that the last content log has the action with the newer description, but the old description is on the card...

bentleycook commented 5 years ago

That said, it's still odd that the last content log has the action with the newer description, but the old description is on the card...

Where are these actions coming from? Are those Action objects coming from Trello or are they generated from the library?

agross commented 5 years ago

@bentleycook

Yes,the template card is one that we regularly make copies of. It's not random, though, we make copies a single template card for this specific use-case.

I can send you the API key via email if you are okay with that.

gregsdennis commented 5 years ago

The actions are coming from Trello. I don't generate any objects that I don't receive from the API.

bentleycook commented 5 years ago

It won't overwrite cached objects with data received inside actions because those are generally historical snapshots rather than current values.

That said, it's still odd that the last content log has the action with the newer description, but the old description is on the card...

This sounds like it might be a caching issue, yeah?

Can you look at the action history for the specific card via a raw HTTP request? https://api.trello.com/1/cards/{idCard}/actions?filter=all&key={yourAPIKey}&token={yourToken} That would show a ledger of Trello's knowledge of the card. I'm also happy to hop in and do this for you. Shoot an email to support@trello.com with the note "Please assign to Bentley" and it will get routed to me. From there I can prompt you to give me temporary account access (this is assuming you're the owner of the cards this is happening on!).

agross commented 5 years ago

Can you look at the action history for the specific card via a raw HTTP request?

See here: trello.json

I again removed all the personal information and replaced the desc values with uppercase strings.

When being read from bottom to top all seems to look OK and the description has been set/replaced once once. There is only one array item mentioning desc at all. It seems the history looks OK, but the result that was displayed on the web UI is not: trello-card.json.txt

@bentleycook I'd like to give you access to the board in question as the content displayed there still is wrong. I'll send an email momentarily.

bentleycook commented 5 years ago

Here are the action IDs, timestamps derived from them, and what each action is doing:

2019-10-18T09:19:33.000Z - 5da983a5c23fe840ea485e18 - Update custom field
2019-10-18T09:19:32.000Z - 5da983a4b67e0e6efe75ec06 - Add attachment
2019-10-18T09:19:32.000Z - 5da983a415d33a091eedcf62 - Update pos
2019-10-18T09:19:32.000Z - 5da983a415d33a091eedcf60 - Update desc
2019-10-18T09:19:32.000Z - 5da983a415d33a091eedcf5e - Update name
2019-10-18T09:19:31.000Z - 5da983a3f7550a0e7228bcd2 - Copy card

Looking at this, I'm led to believe that there is a race condition happening between the pos, desc, and name updates. The Update desc action shows that Trello thinks the desc was correctly updated.

@gregsdennis, your comment from a few days ago was helpful. Can you expand a bit more on the timeline from the library?

L30 - POST to send attachment
L47 - PUT to send custom field value
L52 - Flush all pending requests
L53 - Refresh card data with what Trello has.

When did the PUT request for updating the desc and name fire?

I'll continue to explore this from our end as it definitely looks like a race condition.

gregsdennis commented 5 years ago

@bentleycook it seems that the PUT log entry is missing. It should be the L52 - Flush all pending requests that fires the request to update the pos, desc, and name all in a single PUT request. Looking at the timestamps on the actions, it appears that was the case.

Regarding the request content, it would have only sent those properties ~and the card's ID~. The serializer only serializes non-null properties, and I only set properties that change on the DTO.

@agross looking at the adjustments you made to your code, I'm not entirely sure how setting properties and immediately refreshing would behave.

       card.Description = message.Description;
       card.Position = Position.Top;

+      await card.Refresh(true);

I would expect that it queues that the changes need to occur, but then it receives new data. I don't know how that timing could work out.

agross commented 5 years ago

@gregsdennis I made those changes only after reporting this issue. My impression is that it doesn't significantly influence the outcome. Cards without updated descriptions have been created with or without it.

gregsdennis commented 5 years ago

Yeah, I just ran a test. It looks like the changes are preserved and pushed to the server. This is confirmed by the synchronization code.

agross commented 5 years ago

@bentleycook Are there new insights about this issue?

bentleycook commented 5 years ago

It is in our backlog but hasn't been prioritized.

To ensure that this isn't hit, is it possible to have the library make these calls synchronously?

gregsdennis commented 5 years ago

Yes, it is... kinda. By setting TrelloConfiguration.ChangeSubmissionTime = TimeSpan.Zero; it'll send requests immediately. It'll still be async, though. It won't aggregate calls, either; you'll make a call per change.

agross commented 5 years ago

@gregsdennis Thanks, I'll try that and see if this works around the issue.

gregsdennis commented 4 years ago

@agross any luck?

agross commented 4 years ago

@gregsdennis The workaround you provided appears to have fixed our problems with the card descriptions. I'm in favor of keeping this issue open and hopefully find a solution that does not require to change Manatee.Trello's internal optimizations.