Strange problem when checking for updates after 23.7.7_3 update . .

[rfox]

Here's the results . . .

***GOT REQUEST TO AUDIT CONNECTIVITY***
Currently running OPNsense 23.7.7_3 at Tue Oct 31 10:22:35 CET 2023
Checking connectivity for host: pkg.opnsense.org -> 89.149.222.99
PING 89.149.222.99 (89.149.222.99): 1500 data bytes
1508 bytes from 89.149.222.99: icmp_seq=0 ttl=55 time=12.137 ms
1508 bytes from 89.149.222.99: icmp_seq=1 ttl=55 time=12.140 ms
1508 bytes from 89.149.222.99: icmp_seq=2 ttl=55 time=12.139 ms
1508 bytes from 89.149.222.99: icmp_seq=3 ttl=55 time=12.227 ms

--- 89.149.222.99 ping statistics ---
4 packets transmitted, 4 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 12.137/12.161/12.227/0.038 ms
Checking connectivity for repository (IPv4): https://pkg.opnsense.org/FreeBSD:13:amd64/23.7
Updating OPNsense repository catalogue...
Fetching meta.conf: . done
Fetching packagesite.pkg: .......... done
Processing entries: .......... done
OPNsense repository update completed. 851 packages processed.
Updating SunnyValley repository catalogue...
Fetching meta.conf: . done
Fetching packagesite.pkg: ... done
Processing entries: ....... done
SunnyValley repository update completed. 64 packages processed.
All repositories are up to date.
Checking connectivity for host: pkg.opnsense.org -> 2001:1af8:5300:a010:1::1
PING6(1548=40+8+1500 bytes) 2a01:598:8982:a072:a043:bff:fed0:5d49 --> 2001:1af8:5300:a010:1::1
1508 bytes from 2001:1af8:5300:a010:1::1, icmp_seq=0 hlim=49 time=149.033 ms
1508 bytes from 2001:1af8:5300:a010:1::1, icmp_seq=1 hlim=49 time=55.866 ms
1508 bytes from 2001:1af8:5300:a010:1::1, icmp_seq=2 hlim=49 time=55.509 ms
1508 bytes from 2001:1af8:5300:a010:1::1, icmp_seq=3 hlim=49 time=51.742 ms

--- 2001:1af8:5300:a010:1::1 ping6 statistics ---
4 packets transmitted, 4 packets received, 0.0% packet loss
round-trip min/avg/max/std-dev = 51.742/78.038/149.033/41.021 ms
Checking connectivity for repository (IPv6): https://pkg.opnsense.org/FreeBSD:13:amd64/23.7
Updating OPNsense repository catalogue...

Sits here for a long time . . . seems hung ?!?

Checked the logs:

2023-10-31T10:20:24   Error   configd.py   Timeout (120) executing : firmware remote   
2023-10-31T10:18:22   Error   configd.py   Timeout (120) executing : firmware tiers   
2023-10-31T07:09:24   Error   configd.py   [33319d67-e555-49cf-9475-ca30ebe54b50] returned exit status 1   
2023-10-30T17:48:58   Error   configd.py   [4881b3d8-f351-4c31-86c2-78729c65a82b] Script action failed with Command '/usr/local/opnsense/scripts/firmware/query.sh remote ' returned non-zero exit status 143. at Traceback (most recent call last): File "/usr/local/opnsense/service/modules/actions/script_output.py", line 44, in execute subprocess.check_call(script_command, env=self.config_environment, shell=True, File "/usr/local/lib/python3.9/subprocess.py", line 373, in check_call raise CalledProcessError(retcode, cmd) subprocess.CalledProcessError: Command '/usr/local/opnsense/scripts/firmware/query.sh remote ' returned non-zero exit status 143.   
2023-10-30T17:48:58   Error   configd.py   [113edd75-e752-4bfe-b3f0-936e70a37559] Script action failed with Command '/usr/local/opnsense/scripts/firmware/query.sh remote ' returned non-zero exit status 143. at Traceback (most recent call last): File "/usr/local/opnsense/service/modules/actions/script_output.py", line 44, in execute subprocess.check_call(script_command, env=self.config_environment, shell=True, File "/usr/local/lib/python3.9/subprocess.py", line 373, in check_call raise CalledProcessError(retcode, cmd) subprocess.CalledProcessError: Command '/usr/local/opnsense/scripts/firmware/query.sh remote ' returned non-zero exit status 143.   
2023-10-30T17:48:53   Error   configd.py   [80265804-0d0e-430c-8134-0da4bf5e010d] Script action failed with Command '/usr/local/opnsense/scripts/firmware/query.sh tiers ' returned non-zero exit status 143. at Traceback (most recent call last): File "/usr/local/opnsense/service/modules/actions/script_output.py", line 44, in execute subprocess.check_call(script_command, env=self.config_environment, shell=True, File "/usr/local/lib/python3.9/subprocess.py", line 373, in check_call raise CalledProcessError(retcode, cmd) subprocess.CalledProcessError: Command '/usr/local/opnsense/scripts/firmware/query.sh tiers ' returned non-zero exit status 143.   
2023-10-30T17:48:53   Error   configd.py   [3663a634-0cc7-45b9-a3c4-164e9dfa625a] Script action failed with Command '/usr/local/opnsense/scripts/firmware/query.sh tiers ' returned non-zero exit status 143. at Traceback (most recent call last): File "/usr/local/opnsense/service/modules/actions/script_output.py", line 44, in execute subprocess.check_call(script_command, env=self.config_environment, shell=True, File "/usr/local/lib/python3.9/subprocess.py", line 373, in check_call raise CalledProcessError(retcode, cmd) subprocess.CalledProcessError: Command '/usr/local/opnsense/scripts/firmware/query.sh tiers ' returned non-zero exit status 143.


root@FoxOPN:/home/rfox # ps aux | grep pkg
root           8151   0.0  0.1   22072    7144  -  I    11:54      0:00.01 pkg -6 update -f
root           8600   0.0  0.0   12624    1656  -  IC   11:54      0:00.00 /usr/bin/tee -a /tmp/pkg_upgrade.progress
root           8808   0.0  0.1   22076    7476  -  I    11:54      0:00.01 pkg -6 update -f
root          60335   0.0  0.1   22072    7148  -  I    12:00      0:00.01 pkg update -f
root          60774   0.0  0.1   24772    9392  -  I    12:00      0:00.03 pkg update -f
root          78912   0.0  0.0   12872    1944  -  I    11:54      0:00.00 /usr/local/bin/flock -n -o /tmp/pkg_upgrade.progress /usr/local/opnsense/scripts/firmware/connection.sh
root          99288   0.0  0.0   12724    1936  1  S+   12:02      0:00.00 grep pkg

[rfox]

10 Minutes later - and still hanging - I might try to revert back to 27.7.6 and see if that fixes it . .

***GOT REQUEST TO AUDIT CONNECTIVITY***
Currently running OPNsense 23.7.7_3 at Tue Oct 31 10:22:35 CET 2023
Checking connectivity for host: pkg.opnsense.org -> 89.149.222.99
PING 89.149.222.99 (89.149.222.99): 1500 data bytes
1508 bytes from 89.149.222.99: icmp_seq=0 ttl=55 time=12.137 ms
1508 bytes from 89.149.222.99: icmp_seq=1 ttl=55 time=12.140 ms
1508 bytes from 89.149.222.99: icmp_seq=2 ttl=55 time=12.139 ms
1508 bytes from 89.149.222.99: icmp_seq=3 ttl=55 time=12.227 ms

--- 89.149.222.99 ping statistics ---
4 packets transmitted, 4 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 12.137/12.161/12.227/0.038 ms
Checking connectivity for repository (IPv4): https://pkg.opnsense.org/FreeBSD:13:amd64/23.7
Updating OPNsense repository catalogue...
Fetching meta.conf: . done
Fetching packagesite.pkg: .......... done
Processing entries: .......... done
OPNsense repository update completed. 851 packages processed.
Updating SunnyValley repository catalogue...
Fetching meta.conf: . done
Fetching packagesite.pkg: ... done
Processing entries: ....... done
SunnyValley repository update completed. 64 packages processed.
All repositories are up to date.
Checking connectivity for host: pkg.opnsense.org -> 2001:1af8:5300:a010:1::1
PING6(1548=40+8+1500 bytes) 2a01:598:8982:a072:a043:bff:fed0:5d49 --> 2001:1af8:5300:a010:1::1
1508 bytes from 2001:1af8:5300:a010:1::1, icmp_seq=0 hlim=49 time=149.033 ms
1508 bytes from 2001:1af8:5300:a010:1::1, icmp_seq=1 hlim=49 time=55.866 ms
1508 bytes from 2001:1af8:5300:a010:1::1, icmp_seq=2 hlim=49 time=55.509 ms
1508 bytes from 2001:1af8:5300:a010:1::1, icmp_seq=3 hlim=49 time=51.742 ms

--- 2001:1af8:5300:a010:1::1 ping6 statistics ---
4 packets transmitted, 4 packets received, 0.0% packet loss
round-trip min/avg/max/std-dev = 51.742/78.038/149.033/41.021 ms
Checking connectivity for repository (IPv6): https://pkg.opnsense.org/FreeBSD:13:amd64/23.7
Updating OPNsense repository catalogue...
pkg: https://pkg.opnsense.org/FreeBSD:13:amd64/23.7/latest/meta.txz: Operation timed out
repository OPNsense has no meta file, using default settings
pkg: https://pkg.opnsense.org/FreeBSD:13:amd64/23.7/latest/packagesite.pkg: Operation timed out
pkg: https://pkg.opnsense.org/FreeBSD:13:amd64/23.7/latest/packagesite.txz: Operation timed out
Unable to update repository OPNsense
Updating SunnyValley repository catalogue...
pkg: https://updates.zenarmor.com/opnsense/FreeBSD:13:amd64/23.7/latest/meta.txz: Operation timed out
repository SunnyValley has no meta file, using default settings
pkg: https://updates.zenarmor.com/opnsense/FreeBSD:13:amd64/23.7/latest/packagesite.pkg: Operation timed out

[cookiemonster]

Code Select Expand

penguin@mypc:/tmp$ curl https://pkg.opnsense.org/FreeBSD:13:amd64/23.7
<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>301 Moved Permanently</title>
</head><body>
<h1>Moved Permanently</h1>
<p>The document has moved <a href="https://pkg.opnsense.org/FreeBSD:13:amd64/23.7/">here</a>.</p>
</body></html>

penguin@mypc:/tmp$ wget https://pkg.opnsense.org/FreeBSD:13:amd64/23.7
--2023-10-31 10:55:03--  https://pkg.opnsense.org/FreeBSD:13:amd64/23.7
Resolving pkg.opnsense.org (pkg.opnsense.org)... 89.149.222.99, 2001:1af8:5300:a010:1::1
Connecting to pkg.opnsense.org (pkg.opnsense.org)|89.149.222.99|:443... connected.
HTTP request sent, awaiting response... 301 Moved Permanently
Location: https://pkg.opnsense.org/FreeBSD:13:amd64/23.7/ [following]
--2023-10-31 10:55:04--  https://pkg.opnsense.org/FreeBSD:13:amd64/23.7/
Reusing existing connection to pkg.opnsense.org:443.
HTTP request sent, awaiting response... 200 OK
Length: 1289 (1.3K) [text/html]
Saving to: '23.7'

23.7                          100%[=================================================>]   1.26K  --.-KB/s    in 0s

2023-10-31 10:55:04 (195 MB/s) - '23.7' saved [1289/1289]

All good here and using a work vpn that puts me in a different geographic location.
Maybe some geo thing if the mirror is behind a cdn ?

[franco]

It still looks like flaky IPv6. Maybe better turn it off.


Cheers,
Franco

[rfox]

It still looks like flaky IPv6. Maybe better turn it off.

Cheers,
Franco

Thx Franco - will try.  Strange that it always worked before 27.7.7_3 ?!?  So, how do I turn off IPv6 completely? 

[franco]

Start with your WAN IPv6 mode... it probably still is DHCPv6 from the default setting?


Cheers,
Franco

[rfox]

Turned off DHCPv6 on WAN side (was default) and noticed on the LAN was "Track Interface" turned on ?!? Turned it off.  Using default mirror still failed (couldn't figure out how to release the IPv6 address from console - but oddly enough, I switched to a different mirror "C0urier.net" in Sweden - and because it doesn't have IPv6  everything works as expected.

My question is, when using the Default mirror - why can't it fall back to IPv4 when IPv6 times out?  Something has changed since last update to cause this to fail - was there a script change maybe?

Anyone else affected?  Turning off IPv6 is not really a good solution . . .

Thanks for your help!

[franco]

If the connection appears to contact the server successfully but stalls on the actual download, how can anyone blame IPv6 functionality itself at that point? IPv4 does exactly the same in these situations but it's generally less prone to such intermittent connectivity issues :)

And I'm not sure why you want IPv6 enabled when your connection isn't working as it should as proven here. Ask your provider...


Cheers,
Franco

[rfox]

If the connection appears to contact the server successfully but stalls on the actual download, how can anyone blame IPv6 functionality itself at that point? IPv4 does exactly the same in these situations but it's generally less prone to such intermittent connectivity issues :)

And I'm not sure why you want IPv6 enabled when your connection isn't working as it should as proven here. Ask your provider...


Cheers,
Franco

Understood.  Just for clarity, I did not enable IPv6 on the WAN - it was default set that way.  All I'm saying is - for almost a year of using OPNSense - I have had NO issue with this - then, all of a sudden - after updating to 27.7._3 it started to act real weird.  So, something obviously changed in the latest update to cause this issue.

Thx again!

[franco]

It could be coincidence. Your ISP may have changed something, started rolling out partial IPv6. It has happened a number of times over the years. Usually users see the system mostly on updates and this is when they notice things may not be working as before. To put it in a funny way: "blame update first, reassess situation later" :)

The choice here is to either support IPv6 out of the box for OPNsense or not. For most this will be better than having to enable it manually (more are less likely to even attempt it). It also certainly helps with testing on our end to have this as a standard.

Simply trying to give more context here. I know how difficult the situation is.


Cheers,
Franco

[rfox]

Excellent reply!  ;D I will check with my provider to see if they changed something recently. 

Yet, if I turn off IPv6 and it works fine with a different mirror than the "Default" mirror - that says a lot as well.  I plan to revert to a previous backup 27.7.6 just to see if the issue goes away - that would be more definitive for us!

Thx again and Happy Halloween on top!!