A freelance client that I had previously worked with got in touch with me recently with a pretty urgent problem: in the past week, their WooCommerce Subscriptions were double-charging every customer upon monthly renewal and they, quite urgently, needed this to be fixed.
I wanted to help, not only because I like this client, but because the initial problem was incredibly fascinating to me. There was a slight issue in the fact that whilst I had worked on parts of this website before, I wasn’t the one to do the bulk of the build, so I can be as familiar with the overall WordPress and WooCommerce environment all I want - but a good diagnosis often requires in-depth knowledge of the environment itself. Was there a rogue plugin update? Had an update borked WP Cron? Had some other cowboy developer made a hacky function which was firing off orders twice? I had to find out.
With that, they agreed for me to investigate. We had originally timeboxed the research, but if only I knew how far down the rabbithole I'd go!
The problem
Here is an overview of the situation, as briefed:
- A long-standing WooCommerce store had randomly begun charging customers twice every time a renewal order was processed
- The issue only occurs on renewal orders, not first time or single orders
- Orders within WooCommerce were being processed once, no duplicate orders
- The store is using WooCommerce, WooCommerce Subscriptions, and WooCommerce Stripe Gateway plugins.
- These plugins had been working perfectly fine up until the last week or so
- There had been no additional development work to the store in the last few months
- All plugins had been kept up-to-date
- Stripe wasn't detecting a double-charge and automatically rejecting the second attempt.
The theory
My initial theory was a classic response to most WordPress issues: there's something wrong with the plugins. You know how with server issues, it's always DNS? With WordPress, it's always plugins. I thought that a plugin had gone rogue, messed some data up somewhere, and was sending duplicate payment requests to Stripe.
But with this theory, something wasn't sitting right. The WooCommerce Stripe Gateway has long supported idempotency, which should prevent duplicate charges. Why was Stripe not detecting this?
The investigation
I received logins to the WordPress and got to work routing through some of the example orders that had been sent over. Usually, the immediate first action here would be to check the logs. So like any good developer, I checked that WP_DEBUG_LOG was enabled (it was) and went on my way to investigate the debug.log file.
It was 8GB.
Yikes. My machine struggled to download it, let alone open it - so I guess that looking through that was out of the question for now! Nevertheless, I could explore other options. Luckily, WooCommerce has its own logs that are viewable within the admin panel and in looking at those, I could see that each order was indeed correctly firing off one API request to Stripe.
This was weird. The logs showed absolutely no indication of any duplicate order numbers, no indication of multiple API requests. I was definitely seeing only one order, but two payments in Stripe, referencing this single order.
I was stumped, but even more intrigued. I decided to go the route of enabling debug mode for WooCommerce subscriptions, made a live order and manually processed next months order to see if the issue lay with WP-Cron or with WooCommerce Subscriptions plugin itself.
Initially, I saw only one payment in Stripe, which was reassuring. However, I had made this order at around 11:30pm and decided to call it a night. It wasn't until the morning when I discovered that a second charge had indeed occurred.
The fascinating thing here was that the duplicate charge wasn't within a few minutes of the first attempt - which is what I would expect. After getting access to the clients Stripe account and looking through the duplicate orders, every single one followed the same pattern:
- The second charge would occur around 50-70 minutes after the original
- The
chargeandsourceID were the same, but thepayment_intentIDs were different - The request metadata was mostly the same, but the second charge would include a secondary Order ID
- Both requests were coming from two different IP addresses
The first thing that stood out to me in looking over the orders was that the metadata was slightly different. The overall information (customers name, address original order ID etc.) were the same - but the metadata which referenced that current months order was slightly different. Specifically, the Order ID would be different, and searching these Order IDs in WooCommerce would pull up somebody else's order.
Admittedly, it wasn't until a few hours later where I realised that the biggest red flag was actually source IP addresses for both orders being different where I realised that this could likely be a staging environment which was being synced and accidentally firing two payments requests off. Unfortunately, they have no staging environment.
Slightly concerned at this point, I decided to look up the IP addresses. This is when the penny dropped.
The diagnosis
I ran a DNS lookup for the domain, and the returned IP for their A Record matched the IP address where the original payments in Stripe were originating from, as expected. In checking the DNS records for the second IP address, I couldn't find any matches against the domain so I looked up the IP address itself to see if any ownership details would come to light. The physical location of the second IP was London, the same as the original IP.
Next, I ran a DNS check against the Nameserver domains for the clients host. I had a match. This was the point where all the dots connected and I realised what was happening.
When you point a domain name to a server, a typical method would be to use Nameservers (NS Records). These nameservers are essentially what correctly directs all traffic to your servers IP address when you enter a domain name into your browser.
For speed purposes, webhosts will often instruct you to enter multiple nameservers which usually look like: ns1.awesomewebhost.com, ns2.awesomewebhost.com. This is to spread the load of traffic between multiple servers and ensure the site can go just a little bit faster. It means that behind the scenes, some users will be served the site from Nameserver 1, and others from Nameserver 2. Web hosts will also intelligently cache websites between nameservers for further speed improvements.
Now how does this translate to duplicate charges?
Woocommerce Subscriptions utilises WP-Cron to initiate its scheduled payments. Cron is an automated task scheduler which runs in the background on servers at fixed times. WP-Cron is WordPress' own implementation of Cron, written in PHP.
The main drawback to WP-Cron is that it's written in PHP, and unlike conventional Cron Jobs, scheduled jobs in WP-Cron can only execute once the PHP code is run by the browser. In simplified terms, WP-Cron can only execute once a customer visits the site, whereas conventional Cron can run regardless.
This means that if you schedule a task for 3pm every day - in conventional Cron, this task will run at 3pm regardless. In WP, it will only run when the PHP executes, so if your site gets a visitor at 3:15pm, your WP-Cron Job will run at 3:15pm, not the automated 3pm.
Note: WooCommerce actually uses Action Scheduler - which is an improved system, but still runs via WP-Cron.
Now knowing that WooCommerce Subscriptions only runs when WP-Cron runs, this means that our scheduled renewal charge only initiates when a user visits the site - and in seeing that the two charges come from two IP addresses that are the hosts nameservers, it paints a more clearer picture of what was happening.
The site was being aggressively cached between the two Nameservers. User A would visit the site via Nameserver 1, which triggered WP-Cron/Action Scheduler, initiating a charge and moving the renewal order to a processing status.
Some time later, User B would visit the site via Nameserver 2 - also triggering WP-Cron. Due to the aggressive caching, Nameserver 2 wouldn't see that this order was already in the processing state and think it hasn't begun to be processed yet, so it will run that renewal order and initiate a charge to Stripe.
Stripe would receive the secondary payment coming from a different IP address with slightly different metadata, causing it to fail any idempotency checks because as far as Stripe was concerned, these were two genuine different payments.
In discovering this, I just stopped what I was doing and sat there in relief. I completely disabled any caching from the host and from within WordPress itself - and the problem disappeared.
The conclusion
I really wanted to write this post because from my endless Googling of this issue, I could find no one who had this same issue. Any similar issue I found on Reddit, WordPress Plugin support forums and such were all either rogue plugins or the OP simply stopped replying.
I am writing this for someone who may experience the same issue as me, and I hope it helps someone. There is one lesson to learn that I should have known all along:
It's always DNS.