Freebox Server (Ultra V9/ Pop V8/ Delta V7 / Revolution V6 / Mini 4K)

  • État Fermée
  • Pourcentage achevé
    100%
  • Type Anomalie
  • Catégorie Services locaux → Client VPN
  • Assignée à
    mbizon
  • Système d'exploitation Freebox Server V6 (Révolution)
  • Sévérité Haute
  • Priorité Très Basse
  • Basée sur la version 4.2.0
  • Due pour la version Non décidée
  • Échéance Non décidée
  • Votes
  • Privée
Concerne le projet: Freebox Server (Ultra V9/ Pop V8/ Delta V7 / Revolution V6 / Mini 4K)
Ouverte par Raptor039 - 15/07/2020
Dernière modification par mbizon - 24/07/2020

FS#30991 - Problème de connexion OpenVPN client depuis Freebox V6 4.2.0

Bonjour,

depuis l’upgrade de ma Freebox V6 vers le fimware 4.2.0, le client OpenVPN de la freebox ne monte plus vers mon serveur openvpn auto hébergé (debian 10.4 / OpenVPN 2.4.9 – OpenSSL 1.1.1d)

Je tiens à préciser qu’il ne s’agit pas ici d’un problème de Cipher SSL trop ancien côté serveur comme j’ai pu le voir sur d’autres tickets d’utilisateurs rencontrant également un problème avec le client OpenVPN (et dont leurs serveurs sont chez PureVPN par exemple)

Ci-après le log complet tirés de la Freebox : 

2020-07-15 22:59:59 openvpn: rx: >HOLD:Waiting for hold release:0
2020-07-15 22:59:59 openvpn: tx: hold release
2020-07-15 22:59:59 openvpn: output: Wed Jul 15 22:59:59 2020 MANAGEMENT: CMD 'hold release'
2020-07-15 22:59:59 openvpn: rx: SUCCESS: hold release succeeded
2020-07-15 22:59:59 openvpn: output: Wed Jul 15 22:59:59 2020 MANAGEMENT: CMD 'state on'
2020-07-15 22:59:59 openvpn: rx: SUCCESS: real-time state notification set to ON
2020-07-15 22:59:59 openvpn: output: Wed Jul 15 22:59:59 2020 MANAGEMENT: >STATE:1594846799,WILL_CONNECT,xxx.xxxxx.xxxx,,,,,
2020-07-15 22:59:59 openvpn: output: Wed Jul 15 22:59:59 2020 Outgoing Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
2020-07-15 22:59:59 openvpn: output: Wed Jul 15 22:59:59 2020 Incoming Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
2020-07-15 22:59:59 openvpn: output: Wed Jul 15 22:59:59 2020 MANAGEMENT: >STATE:1594846799,RESOLVE,,,,,,
2020-07-15 22:59:59 openvpn: output: Wed Jul 15 22:59:59 2020 TCP/UDP: Preserving recently used remote address: [AF_INET]XX.XX.XX.XX:YYYYY
2020-07-15 22:59:59 openvpn: output: Wed Jul 15 22:59:59 2020 Socket Buffers: R=[180224->180224] S=[180224->180224]
2020-07-15 22:59:59 openvpn: output: Wed Jul 15 22:59:59 2020 UDP link local: (not bound)
2020-07-15 22:59:59 openvpn: output: Wed Jul 15 22:59:59 2020 UDP link remote: [AF_INET]XX.XX.XX.XX:YYYYY
2020-07-15 22:59:59 openvpn: output: Wed Jul 15 22:59:59 2020 MANAGEMENT: >STATE:1594846799,WAIT,,,,,,
2020-07-15 22:59:59 openvpn: rx: >STATE:1594846799,WILL_CONNECT,xxx.xxxxx.xxxx,,,,,
2020-07-15 22:59:59 openvpn: rx: >STATE:1594846799,RESOLVE,,,,,,
2020-07-15 22:59:59 openvpn: rx: >STATE:1594846799,WAIT,,,,,,
2020-07-15 22:59:59 openvpn: output: Wed Jul 15 22:59:59 2020 MANAGEMENT: >STATE:1594846799,AUTH,,,,,,
2020-07-15 22:59:59 openvpn: output: Wed Jul 15 22:59:59 2020 TLS: Initial packet from [AF_INET]XX.XX.XX.XX:YYYYY, sid=3b917e26 86122721
2020-07-15 22:59:59 openvpn: rx: >STATE:1594846799,AUTH,,,,,,
2020-07-15 22:59:59 openvpn: output: Wed Jul 15 22:59:59 2020 VERIFY OK: depth=1, C=XX, ST=XXXXX, L=XXXXX, O=XXXX, CN=XXXXXX CA, name=XXXXXX, emailAddress=xxxxxxxxxxxxxxxxxxx
2020-07-15 23:00:00 openvpn: output: Wed Jul 15 23:00:00 2020 VERIFY KU OK
2020-07-15 23:00:00 openvpn: output: Wed Jul 15 23:00:00 2020 Validating certificate extended key usage
2020-07-15 23:00:00 openvpn: output: Wed Jul 15 23:00:00 2020 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
2020-07-15 23:00:00 openvpn: output: Wed Jul 15 23:00:00 2020 VERIFY EKU OK
2020-07-15 23:00:00 openvpn: output: Wed Jul 15 23:00:00 2020 VERIFY OK: depth=0, C=XX, ST=XXXX, L=XXXXXX, O=XXXX, CN=XXXXXX, name=XXXXXX, emailAddress=xxxxxxxxxxxxxxx
2020-07-15 23:00:00 openvpn: output: Wed Jul 15 23:00:00 2020 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 4096 bit RSA
2020-07-15 23:00:00 openvpn: output: Wed Jul 15 23:00:00 2020 [XXXXXX] Peer Connection Initiated with [AF_INET]XX.XX.XX.XX:YYYYY
2020-07-15 23:00:01 openvpn: rx: >STATE:1594846801,GET_CONFIG,,,,,,
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 MANAGEMENT: >STATE:1594846801,GET_CONFIG,,,,,,
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 SENT CONTROL [XXXXXX]: 'PUSH_REQUEST' (status=1)
2020-07-15 23:00:01 openvpn: rx: >STATE:0,CONN_PARAMS,local4-xxx.xxxxx.xxxx|netmask4-xxx.xxxxx.xxxx|dns4-xxx.xxxxx.xxxx|mtu-1500
2020-07-15 23:00:01 openvpn: rx: >STATE:1594846801,CONNECTED,SUCCESS,xxx.xxxxx.xxxx,xxx.xxxxx.xxxx,xxxxx,,
2020-07-15 23:00:01 l3 is now stable
2020-07-15 23:00:01 calling helper script at '/etc/fbxconnman/conn.up'
2020-07-15 23:00:01 l3 state change 'l3_wait_stable' => 'l3_wait_up_helper'
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS xxx.xxxxx.xxxx,route-gateway 10.80.81.1,topology subnet,ping 10,ping-restart 120,ifconfig xxx.xxxxx.xxxx xxx.xxxxx.xxxx,peer-id 0,cipher AES-256-GCM'
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 OPTIONS IMPORT: timers and/or timeouts modified
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 OPTIONS IMPORT: --ifconfig/up options modified
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 OPTIONS IMPORT: route-related options modified
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 OPTIONS IMPORT: peer-id set
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 OPTIONS IMPORT: adjusting link_mtu to 1624
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 OPTIONS IMPORT: data channel crypto options modified
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 Data Channel: using negotiated cipher 'AES-256-GCM'
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 Initialization Sequence Completed
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 MANAGEMENT: >STATE:0,CONN_PARAMS,local4-xxx.xxxxx.xxxx|netmask4-xxx.xxxxx.xxxx|dns4-xxxxxxxxxxx|mtu-1500
2020-07-15 23:00:01 openvpn: output: 
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 MANAGEMENT: >STATE:1594846801,CONNECTED,SUCCESS,xxx.xxxxx.xxxx,xxx.xxxxx.xxxx,xxxxx,,
2020-07-15 23:00:01 helper err: Command line is not complete. Try option "help"
2020-07-15 23:00:01 helper script terminated with signal 127
2020-07-15 23:00:01 unable to apply l3 parameters
2020-07-15 23:00:01 l3 state change 'l3_wait_up_helper' => 'l3_bring_down'
2020-07-15 23:00:01 waiting for l3 providers to go down
2020-07-15 23:00:01 l3 state change 'l3_bring_down' => 'l3_wait_down'
2020-07-15 23:00:01 openvpn: rx: >STATE:1594846801,EXITING,SIGTERM,,,,,
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 event_wait : Interrupted system call (code=4)
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 Closing TUN/TAP interface
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 SIGTERM[hard,] received, process exiting
2020-07-15 23:00:01 openvpn: output: Wed Jul 15 23:00:01 2020 MANAGEMENT: >STATE:1594846801,EXITING,SIGTERM,,,,,
2020-07-15 23:00:01 calling helper script at '/etc/fbxconnman/conn.down'
2020-07-15 23:00:01 l3 state change 'l3_wait_down' => 'l3_wait_down_helper'
2020-07-15 23:00:01 openvpn: openvpn process died (0)
2020-07-15 23:00:01 helper script terminated with bad status 1
2020-07-15 23:00:01 l3 state change 'l3_wait_down_helper' => 'l3_cleanup_start'
2020-07-15 23:00:01 calling helper script at '/etc/fbxconnman/conn.post-down'
2020-07-15 23:00:01 l3 state change 'l3_cleanup_start' => 'l3_wait_postdown_helper'
2020-07-15 23:00:01 l3 state change 'l3_wait_postdown_helper' => 'l3_cleanup_finish'
2020-07-15 23:00:01 l3 state change 'l3_cleanup_finish' => 'l3_finished'
2020-07-15 23:00:01 state change 'wait_l3_up' => 'wait_l3_down'
2020-07-15 23:00:01 l3 state change 'l3_finished' => 'l3_down'
2020-07-15 23:00:01 state is now DOWN
2020-07-15 23:00:01 state change 'wait_l3_down' => 'l3_finished'
2020-07-15 23:00:01 state change 'l3_finished' => 'wait_l2_down'
2020-07-15 23:00:01 l2 state change 'l2_up' => 'l2_cleanup'
2020-07-15 23:00:01 l2 state change 'l2_cleanup' => 'l2_down'
2020-07-15 23:00:01 state change 'wait_l2_down' => 'down'
23:02

Ce qui ressort en erreur du log : 

2020-07-15 23:00:01 helper err: Command line is not complete. Try option "help"
2020-07-15 23:00:01 helper script terminated with signal 127
2020-07-15 23:00:01 unable to apply l3 parameters
2020-07-15 23:00:01 l3 state change 'l3_wait_up_helper' => 'l3_bring_down'

Merci d’avance pour la prise en charge de cet incident.

Je reste bien entendu à disposition pour plus d’infos si besoin, côté serveur par exemple.

Cordialement.

Fermée par  mbizon
24.07.2020 12:06
Raison de la fermeture :  Résolu
Commentaires de fermeture :  

en 4.2.2

Admin
mbizon a commenté le 15.07.2020 21:48

Bonjour,

Pourrais-je avoir l'adresse MAC de votre Freebox svp ?

Raptor039 a commenté le 16.07.2020 05:52

Bonjour,

merci pour la rapidité de prise en charge de ma demande.

La Mac Address est la suivante : 68:A3:78:74:25:4A

Dans tous les cas, je vois que vous ne chômez pas et vous en remercie ! Bon courage à vous !

Bonne journée.

Raptor039 a commenté le 16.07.2020 06:29

Ci-après les logs côté serveur si jamais ça peut vous aider : 

Wed Jul 15 23:20:29 2020 xx.xx.xx.xx:33796 TLS: Initial packet XXom [AF_INET]xx.xx.xx.xx:33796, sid=83872b13 5bba5986
Wed Jul 15 23:20:30 2020 xx.xx.xx.xx:33796 VERIFY OK: depth=1, C=XX, ST=XX, L=XX, O=XX, CN=XX, name=XX, emailAddress=xxxxxx
Wed Jul 15 23:20:30 2020 xx.xx.xx.xx:33796 VERIFY OK: depth=0, C=XX, ST=XX, L=XX, O=XX, CN=xx, name=xxxxx, emailAddress=xxxxx
Wed Jul 15 23:20:30 2020 xx.xx.xx.xx:33796 peer info: IV_VER=2.4.7
Wed Jul 15 23:20:30 2020 xx.xx.xx.xx:33796 peer info: IV_PLAT=linux
Wed Jul 15 23:20:30 2020 xx.xx.xx.xx:33796 peer info: IV_PROTO=2
Wed Jul 15 23:20:30 2020 xx.xx.xx.xx:33796 peer info: IV_NCP=2
Wed Jul 15 23:20:30 2020 xx.xx.xx.xx:33796 peer info: IV_LZ4=1
Wed Jul 15 23:20:30 2020 xx.xx.xx.xx:33796 peer info: IV_LZ4v2=1
Wed Jul 15 23:20:30 2020 xx.xx.xx.xx:33796 peer info: IV_LZO=1
Wed Jul 15 23:20:30 2020 xx.xx.xx.xx:33796 peer info: IV_COMP_STUB=1
Wed Jul 15 23:20:30 2020 xx.xx.xx.xx:33796 peer info: IV_COMP_STUBv2=1
Wed Jul 15 23:20:30 2020 xx.xx.xx.xx:33796 peer info: IV_TCPNL=1
Wed Jul 15 23:20:30 2020 xx.xx.xx.xx:33796 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 4096 bit RSA
Wed Jul 15 23:20:30 2020 xx.xx.xx.xx:33796 [freebox] Peer Connection Initiated with [AF_INET]xx.xx.xx.xx:33796
Wed Jul 15 23:20:30 2020 freebox/xx.xx.xx.xx:33796 MULTI_sva: pool returned IPv4=1xx.xx.xx.xx, IPv6=(Not enabled)
Wed Jul 15 23:20:30 2020 freebox/xx.xx.xx.xx:33796 MULTI: Learn: 10.80.81.2 -> freebox/xx.xx.xx.xx:33796
Wed Jul 15 23:20:30 2020 freebox/xx.xx.xx.xx:33796 MULTI: primary virtual IP for freebox/xx.xx.xx.xx:33796: 10.80.81.2
Wed Jul 15 23:20:31 2020 freebox/xx.xx.xx.xx:33796 PUSH: Received control message: 'PUSH_REQUEST'
Wed Jul 15 23:20:31 2020 freebox/xx.xx.xx.xx:33796 SENT CONTROL [freebox]: 'PUSH_REPLY,dhcp-option DNS xx.xx.xx.xx,route-gateway 10.80.81.1,topology subnet,ping 10,ping-restart 120,ifconfig 10.80.81.2 255.255.255.0,peer-id 0,cipher AES-256-GCM' (status=1)
Wed Jul 15 23:20:31 2020 freebox/xx.xx.xx.xx:33796 Data Channel: using negotiated cipher 'AES-256-GCM'
Wed Jul 15 23:20:31 2020 freebox/xx.xx.xx.xx:33796 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Wed Jul 15 23:20:31 2020 freebox/xx.xx.xx.xx:33796 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Wed Jul 15 23:24:31 2020 freebox/xx.xx.xx.xx:33796 [freebox] Inactivity timeout (--ping-restart), restarting
Wed Jul 15 23:24:31 2020 freebox/xx.xx.xx.xx:33796 SIGUSR1[soft,ping-restart] received, client-instance restarting
Admin
mbizon a commenté le 16.07.2020 09:33

je ne trouve rien dans les logs de cette freebox, vous avez supprimé le vpn ?

Raptor039 a commenté le 16.07.2020 10:10

Pas supprimé, seulement désactivé la connexion pour éviter de spammer mon serveur avec les retry.

Je vais le relancer de suite.

Raptor039 a commenté le 16.07.2020 10:12

Vous devriez voir les logs maintenant

Admin
mbizon a commenté le 16.07.2020 10:33

ok je vous corrige ça

en attendant si vous ajoutez une gateway ça devrait corriger le problème

coté serveur, un truc du genre:

–route network/IP [netmask] [gateway] [metric]
push "route 10.10.10.0 255.255.255.0 10.0.0.2 1"

Raptor039 a commenté le 16.07.2020 12:18

Vous devriez voir les logs maintenant

Raptor039 a commenté le 16.07.2020 12:41

Désolé pour le commentaire précédant, erreur de ma part.

Du coup j'ai suivi vos conseils et ai ajouté un push depuis le serveur pour configurer une static route côté client (ici la freebox) pour le network 10.80.81.0/24 (subnet OpenVPN dédié pour la freebox) avec pour gw 10.80.81.1 (gateway OpenVPN pour ce subnet sur le serveur) et effectivement ça fonctionne de nouveau correctement. Merci pour l'astuce!

Par contre, quand vous dites que vous allez "me corriger ça" c'est bien dans le cadre d'un patch global de la Freebox n'est ce pas ?

Avez-vous néanmoins réussi à déceler l'origine du problème ?

Admin
mbizon a commenté le 16.07.2020 12:50

oui c'est la box qui n'aime pas l'absence de gateway, ça sera corrigé dans le prochain firmware

Raptor039 a commenté le 16.07.2020 13:03

Vivement WireGuard... ;)

Dans tous les cas un grand merci pour l'efficacité de la prise en charge et bon courage pour la suite!

Bonne journée.

Chargement...

Activer les raccourcis clavier

Liste des tâches

Détails de la tâche

Édition de la tâche