Some source registries provide the CDN download addresses to enable users in different regions to download files quickly. When a user requests the source address to download files, the source address will be redirected to the CDN address to speed up the download job. When the source registry of the redirected download address is required using an Artifactory remote repository agent, we may encounter a timeout resolve issue.
Issue The following is an example of this issue:
When we use the npm remote repo proxying https://registry.npmmirror.com to download NPM packages, the download will be slow, and get the redirect errors in the artifactory-service.log as follows:
# artifactory-service.log 2023-11-30T08:31:41.507Z [1;32m[jfrt ][0;39m [1;31m[ERROR][0;39m [aa01d51dfc3bf331] [FrogDefaultRedirectStrategy:66] [ttp-nio-8081-exec-26] - Unable to determine if redirect should be blocked because of the following: Timed out while trying to resolve cdn.npmmirror.com./ANY, id=23074
And we can see the download npm package task took a long time in the artifactory-request.log.
# artifactory-request.log 2023-11-30T08:31:42.355Z|aa01d51dfc3bf331|<client_ip>|anonymous|GET|/api/npm/npmmirror-npm-remote/@codemirror/language/-/language-6.9.3.tgz|200|-1|78469|10960|npm/6.14.17 node/v14.21.2 linux x64
Troubleshooting Step 1: Enable the debug logs in the Artifactory Since the error in the log indicates that the slow download may be due to a network timeout, we can enable the Artifactory HTTP logs as follows to monitor the issue:
- Edit the $JFROG_HOME/var/etc/artifactory/logback.xml file to add the HTTP debug and root debug config like the following.
- After editing, we can see the artifactory-http.log under $JFROG_HOME/var/log
- Note: The "http" debug logging configuration will slow down some operations due to heavy logging. Please remove it after you are done testing the connection.
<!-- etc/artifactory/logback.xml -->
<!-- You should temporarily enable this logger for debugging purpose, then remove it! -->
<appender name="http" class="ch.qos.logback.core.rolling.RollingFileAppender">
<File>${log.dir}/artifactory-http.log</File>
<rollingPolicy class="org.jfrog.common.logging.logback.rolling.FixedWindowWithDateRollingPolicy">
<FileNamePattern>${log.dir.archived}/artifactory-http.%i.log.gz</FileNamePattern>
<maxIndex>10</maxIndex>
</rollingPolicy>
<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
<MaxFileSize>25MB</MaxFileSize>
</triggeringPolicy>
<encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
<layout class="org.jfrog.common.logging.logback.layout.BackTracePatternLayout">
<pattern>%date{yyyy-MM-dd'T'HH:mm:ss.SSS, UTC}Z [jfrt ] [%-5p] [%-16X{uber-trace-id}] [%-30.30(%c{3}:%L)] [%-20.20thread] - %m%n</pattern>
</layout>
</encoder>
</appender>
<logger name="org.apache.http" additivity="false">
<level value="TRACE"/>
<appender-ref ref="http"/>
</logger>
<!-- Ensure the logger and appender both go before the end line -->
</configuration>
Step 2: Pull the npm package through the client again and check the debug logs - Run the npm install command to install the npm package from the npm remote repository in the Artifactory.
- Trace the debug logs to check npm install requests.
- The artifactory-request.log shows the npm install request consumes 10960ms.
# artifactory-request.log 2023-11-30T08:31:42.355Z|aa01d51dfc3bf331|<client_ip>|anonymous|GET|/api/npm/npmmirror-npm-remote/@codemirror/language/-/language-6.9.3.tgz|200|-1|78469|10960|npm/6.14.17 node/v14.21.2 linux x64
- The artifactory-service.log shows the redirect timeout error.
023-11-30T08:31:41.507Z [1;32m[jfrt ][0;39m [1;31m[ERROR][0;39m [aa01d51dfc3bf331] [FrogDefaultRedirectStrategy:66] [ttp-nio-8081-exec-26] - Unable to determine if redirect should be blocked because of the following: Timed out while trying to resolve cdn.npmmirror.com./ANY, id=23074 2023-11-30T08:31:41.508Z [1;32m[jfrt ][0;39m [39m[DEBUG][0;39m [aa01d51dfc3bf331] [FrogDefaultRedirectStrategy:68] [ttp-nio-8081-exec-26] - Unable to determine if redirect should be blocked because of the following: java.io.IOException: Timed out while trying to resolve cdn.npmmirror.com./ANY, id=23074 at org.xbill.DNS.Resolver.send(Resolver.java:170) at org.jfrog.client.util.DenylistValidator.getSupportedType(DenylistValidator.java:154) at org.jfrog.client.util.DenylistValidator.isBlocked(DenylistValidator.java:85) at org.jfrog.client.http.JFrogDefaultRedirectStrategy.shouldBlockRedirect(JFrogDefaultRedirectStrategy.java:64) at org.jfrog.client.http.JFrogDefaultRedirectStrategy.isRedirected(JFrogDefaultRedirectStrategy.java:53) .....
- Checking the artifactory-http.log we can get the job sending the request to https://registry.npmmirror.com at first and the target address returns the 302 status which means a redirect to the download address to https://cdn.npmmirror.com.
# artifactory-http.log
# the request:
2023-11-30T08:31:31.410Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.c.p.RequestAuthCache:77 ] [ttp-nio-8081-exec-26] - Auth cache not set in the context
2023-11-30T08:31:31.411Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [ttpClientConnectionManager:267] [ttp-nio-8081-exec-26] - Connection request: [route: {s}->https://registry.npmmirror.com:443][total available: 7; route allocated: 7 of 50; total allocated: 7 of 50]
2023-11-30T08:31:31.411Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [ttpClientConnectionManager:312] [ttp-nio-8081-exec-26] - Connection leased: [id: 19603][route: {s}->https://registry.npmmirror.com:443][total available: 6; route allocated: 7 of 50; total allocated: 7 of 50]
2023-11-30T08:31:31.411Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [ManagedHttpClientConnection:88] [ttp-nio-8081-exec-26] - http-outgoing-19603: set socket timeout to 30000
2023-11-30T08:31:31.411Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [ManagedHttpClientConnection:88] [ttp-nio-8081-exec-26] - http-outgoing-19603: set socket timeout to 30000
2023-11-30T08:31:31.411Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.i.e.MainClientExec:255 ] [ttp-nio-8081-exec-26] - Executing request GET /@codemirror/language/-/language-6.9.3.tgz HTTP/1.1
2023-11-30T08:31:31.411Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.i.e.MainClientExec:260 ] [ttp-nio-8081-exec-26] - Target auth state: UNCHALLENGED
2023-11-30T08:31:31.412Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.i.e.MainClientExec:266 ] [ttp-nio-8081-exec-26] - Proxy auth state: UNCHALLENGED
2023-11-30T08:31:31.412Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:133 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 >> GET /@codemirror/language/-/language-6.9.3.tgz HTTP/1.1
2023-11-30T08:31:31.412Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:136 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 >> Connection: Keep-Alive
2023-11-30T08:31:31.412Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:136 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 >> X-Artifactory-Originated: 3c5d0a5882bf4c5e:-7723215e:18c0f6701bf:-8000
2023-11-30T08:31:31.412Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:136 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 >> Origin-Artifactory: 3c5d0a5882bf4c5e:-7723215e:18c0f6701bf:-8000
2023-11-30T08:31:31.412Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:136 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 >> Accept-Encoding: gzip
2023-11-30T08:31:31.412Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:136 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 >> uber-trace-id: aa01d51dfc3bf331:aa01d51dfc3bf331:aa01d51dfc3bf331:0
2023-11-30T08:31:31.413Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:136 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 >> Host: registry.npmmirror.com
2023-11-30T08:31:31.413Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:136 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 >> User-Agent: Artifactory/7.71.3 77103900
....
# the response:
2023-11-30T08:31:31.501Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:122 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << HTTP/1.1 302 Moved Temporarily
2023-11-30T08:31:31.501Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << Server: Tengine
2023-11-30T08:31:31.501Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << Content-Type: text/html; charset=utf-8
2023-11-30T08:31:31.501Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << Content-Length: 195
2023-11-30T08:31:31.501Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << Connection: keep-alive
2023-11-30T08:31:31.502Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << Strict-Transport-Security: max-age=5184000
2023-11-30T08:31:31.502Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << Date: Thu, 30 Nov 2023 08:31:31 GMT
2023-11-30T08:31:31.502Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << Vary: Origin
2023-11-30T08:31:31.502Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << request-id: dd1bcf80-8f5a-11ee-a794-8d17105837ca
2023-11-30T08:31:31.502Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << Location: https://cdn.npmmirror.com/packages/%40codemirror/language/6.9.3/language-6.9.3.tgz
2023-11-30T08:31:31.502Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << x-frame-options: SAMEORIGIN
2023-11-30T08:31:31.502Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << x-xss-protection: 1; mode=block
2023-11-30T08:31:31.503Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << x-download-options: noopen
2023-11-30T08:31:31.503Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << x-readtime: 0.731
2023-11-30T08:31:31.503Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << Via: cn5222.l1, kunlun12.cn5222, l2cn3084.l2, cache12.l2cn3084, registry.npmmirror.com-06, cache12.l2cn3084[32,31,302-0,M], cache26.l2cn3084[33,0], kunlun12.cn5222[47,47,302-0,M], kunlun4.cn5222[50,0]
2023-11-30T08:31:31.503Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << Ali-Swift-Global-Savetime: 1701333091
2023-11-30T08:31:31.504Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << X-Cache: MISS TCP_MISS dirn:-2:-2
2023-11-30T08:31:31.504Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << X-Swift-SaveTime: Thu, 30 Nov 2023 08:31:31 GMT
2023-11-30T08:31:31.505Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << X-Swift-CacheTime: 0
2023-11-30T08:31:31.506Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << Timing-Allow-Origin: *
2023-11-30T08:31:31.506Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.headers:125 ] [ttp-nio-8081-exec-26] - http-outgoing-19603 << EagleId: b659c00417013330914226683e
2023-11-30T08:31:31.506Z [jfrt ] [DEBUG] [aa01d51dfc3bf331] [o.a.h.i.e.MainClientExec:285 ] [ttp-nio-8081-exec-26] - Connection can be kept alive for 30000 MILLISECONDS
Step 3: Check that DNS resolves correctly As can be seen from the above debug logs, a timeout occurred when the redirect address, https://cdn.npmmirror.com./ANY, was resolved by DNS where Artifactory sent requests to. After the timeout was complete, the package was downloaded again, resulting in a slow download of this npm package.
- We can use the dig tool to check if DNS can resolve the address correctly.
# Run the dig command to test dig cdn.npmmirror.com./ANY @<dns_ip> # The response of timeout ; <<>> DiG 9.11.4-P2-RedHat-9.11.4-26.P2.el7_9.15 <<>> cdn.npmmirror.com./ANY ;; global options: +cmd ;; connection timed out; no servers could be reached
Resolution - The cause of this issue is that the DNS does not allow the resolution addresses including ANY type. We can adjust the DNS resolution policy to resolve this issue.
- For BIND (Berkeley Internet Name Domain) servers, you need to enable ANY type of record in the configuration file (usually named.conf). This usually involves adding an allow-query directive to the options section to allow queries on records of ANY type.
- In your zone file (such as db.example.com), you can add ANY type records for each subdomain. This is usually a * symbol followed by a space, followed by the record value. For example:
*.cdn.npmmirror.com. IN ANY A 192.0.2.1 *.cdn.npmmirror.com. IN ANY MX 10 mail.cdn.npmmirror.com. *.cdn.npmmirror.com. IN ANY TXT "example text"
- Alternatively, we can edit the /etc/resolv.conf file in the system and annotate the DNS nameserver, then configure the domain name for the request address to be resolved in the /etc/hosts file.
- Edit the /etc/resolv.conf file to comment on the nameserver
- Use the dig tool to query the IP addresses of source registry domain names and cdn domain names and add It in the /etc/hosts file.
# Run the dig command to test dig cdn.npmmirror.com # the result: ; <<>> DiG 9.11.4-P2-RedHat-9.11.4-26.P2.el7_9.15 <<>> cdn.npmmirror.com ...... ;; ANSWER SECTION: cdn.npmmirror.com. 55 IN CNAME cdn.npmmirror.com.w.cdngslb.com. cdn.npmmirror.com.w.cdngslb.com. 55 IN A 111.32.208.176 cdn.npmmirror.com.w.cdngslb.com. 55 IN A 111.32.208.178 ......
# add the ip addr to the /etc/hosts 111.32.208.176 cdn.npmmirror.com