Themekit: theme watch command taking a long time to start

[lesterdefreitas]

Describe the bug
Running the theme watch command seems to take much longer since the latest version update

To Reproduce
Steps to reproduce the behavior:

1. run command theme watch

Expected behavior
You should see that you have to wait 15-20 seconds for the command to run

Environment (please complete the following information):

• MacOS
• Themekit version 1.0.3

[tanema]

hey @lesterdefreitas thanks for opening an issue. Is your theme quite large? In version 1.0.2 functionality was added to take a checksum of each file at startup so that only changes needed to be uploaded. This prevented other changes like editors changing timestamps when you open the file. I could see this functionality slowing down on larger themes

I can probably speed it up by running it in parallel. I will try to do this soon

[anulman]

Does the checksum validate on deploy as well? I'm finding watch works fast enough, but deploy runs through every file

[tanema]

deploy does every file because it has nothing to compare to. However, I am working on a project to make this faster soon.

[anulman]

Makes sense enough! Looking forward to this project. Thanks for all the work @tanema — it's been a lot of fun to get oriented w/ Shopify build tooling :)

[lesterdefreitas]

@tanema Thanks for the response. I am seeing a slow start up time for theme watch on any theme, big or small. I am not sure if it is perhaps just a local network issue then. But once it starts up it runs as fast as I am used to. So I just thought I would mention it in case it is a bug of some sort.

At the moment I am getting an average start time of 25-30s before theme watch actually starts.

[tanema]

If your normal requests are not slow I am not sure why the start-up request would slow it down. At startup, themekit makes 2 requests, 1 to get your shop info to make sure that the Shop you have provided is correct and another to query your themes to make sure the token you have provided is correct and provide any information about the themes like if you are working on a live theme. If you are not seeing themekit respond slowly to other requests then I am not sure that those would be the source of your issues.

[chrisjonesio]

Thought I'd add my 2 cents on this.

I'm also seeing a 20+ second lag running a simple theme version. I do this because I get a timeout error when running theme watch in an npm script. After running theme version a number of times (it changes day to day, I'm over 20 so far while writing this) it'll eventually return very quickly so I know I can run my npm script without it timing out. Once it gets running it goes all day without issue.

Is there a log or some debugging I can do to see what might be the problem? I don't like being the _"hey this thing doesn't work"_ person without at least providing some helpful information. As mentioned by others the network is flying along in other contexts.

This particular theme is on a password-enabled store if that makes any difference (which I doubt).
MacOS 10.15.2, node v12.2.0, pretty lean theme at this point, around 2.5MB including assets.

[tanema]

This is the entirety of the version command source code https://github.com/Shopify/themekit/blob/master/cmd/theme.go#L63-L70

No context is built for that command so no communication with shopify happens however it does pin https://shopify-themekit.s3.amazonaws.com/releases/latest.json to check for releases.

Thanks, @chrisjonesio for your info because that may actually be the key in all of this. It may be that the releases JSON is taking too long to fetch. This is surprising because it is coming from S3 but no unheard of. Try running a curl on the URL and see how long the response is. If this is truely the issue I may have to take out the checking for updates at startup and just let people run it once in a while. (Not ideal for me but maybe more ideal for everyone else)

[chrisjonesio]

Excellent! It's returning quickly now (and I'm off and running using themekit) so I'll curl it first thing tomorrow morning as part of my cracking my knuckles and pouring my coffee routine and will report back.

[chrisjonesio]

Got a chance to curl the version json this morning before I did anything. I first ran theme version to make sure it was taking time and it did. Then ran the curl and it returned with data immediately. So I think we can rule that out.

I did notice though that I was timing the theme version command and it returned in 30 seconds every time. I ran it six times before posting here and they all took 30 seconds. Not sure the 30s has any real meaning but I thought it interesting it was the same every time, like it was some kind of timeout or something.

[tanema]

If it is not that request then it may just be the OS interfering or adding overhead to application startup which is harder to analyze. I will try and build a test binary for you to try out

[anulman]

30s is a pretty typical timeout default — what about using an HTTP monitor (like Charles) to see if requests are timing out?

[tanema]

If anyone can try with charles I would appreciate it. I cannot reproduce this locally. Also the update requests do not get handled with the shopify client so the proxy request is not proxied so you cannot use a tool like mitmproxy to log that traffic.

[chrisjonesio]

@tanema I'll try this first thing Monday morning and post the results here

[chrisjonesio]

Installed Charles proxy this morning, let it sit there for a minute so I could see all my network traffic being logged. Ran theme watch and it returned immediately with no record in Charles. Ran 'theme watch' and it started immediately with no timeout error.

So I have no idea what's going on now but I'll keep my eye on it every morning, but for today it's behaving as expected.

[tanema]

🤦‍♂ A bug that changes when you look at it is the worse kind to fix. Thank you for your persistence @chrisjonesio

[tanema]

Okay, another thing to try is to use the --no-update-notifier flag. It essentially skips the startup, update check.

Edit: If this is really what is happening, I will cut a release really soon to just remove this check

[lesterdefreitas]

Okay, another thing to try is to use the --no-update-notifier flag. It essentially skips the startup, update check.

Edit: If this is really what is happening, I will cut a release really soon to just remove this check

@tanema When would you use this? Everytime you use theme watch?

EG: theme watch --no-update-notifier

[sinak]

It seems like something between 1.0.2 and 1.0.3 made it much worse than it was. theme watch takes about 2 seconds to start for me with 1.0.2 but that jumped to 5+ seconds with 1.0.3.

[tanema]

Between those versions, checksum evaluation was added at startup during watch but it really shouldn't take that long. I will look into that as well. If it is as you say then it is probably the checksum evaluation

[lmartins]

Started to get this error for the commands theme watch and theme get. No matter what timeout value I put in it always gives out the error. Anyone had any luck figuring this one out? The --no-update-notifier seems to make no difference to me.

A colleague on the same network running version 1.0.1 has no issues. I'm on 1.0.2.

[chrisjonesio]

@lmartins I had the issue appear on a project out of nowhere, stick around for a while, then go away without me doing anything specific. I'm running ThemeKit 1.0.3 darwin/amd64 without any timeout issues at this point anymore.

Not sure if it was a node update (running v12.2.0 on this particular project) or something else I haven't noticed, it just went away on its own. Frustrating for sure.

[lmartins]

@chrisjonesio yeah, this totally undermines my trust on this system. For me it started yesterday and I have yet to be able to work on a site since :( Every single command results in a timeout.

[tanema]

This should now be fixed or at least noticeably better as of 1.1.0. Before that release, themekit would calculate the checksums of all files in the project to reduce API calls for unnecessary changes, now however we have added checksums that are available to the API for checking the content. This means it should be a single API call to populate a map of what the content on the server is and if the files on your FS are different.

Please let me know if this has made any difference for you.