Kein Smartphone-Tethering im laufenden Betrieb möglich

[luka]

Hallo zusammen,

Ich habe Probleme beim Verbinden von PC und Smartphone um den Internetzugang des Smartphones auch am PC zu nutzen ("Tethering").

Wenn ich das Smartphone (LG-P700) vor dem Hochfahren des Rechners verbinde, funktioniert alles wunderbar. Versuche ich das Smartphone aber im laufenden Betrieb anzuschließen, erkennt der NetworkManager zwar das Smartphone, kann aber per dhcp keine Adresse beziehen, unternimmt mehrfache Versuche, die jedesmal mit "Verbindung gescheitert" enden, und schließlich "Verbindung getrennt", um dann zu behaupten "Kabel nicht angeschlossen".

Einen Workaround habe ich zwar gefunden, indem ich a) den Network-Manager stoppe b) sofern das Smartphone bereits angeschlossen war und dann abgezogen wurde, die Module cdc_acm und cdc_ether entferne c) das Smartphone anschließe und d) den NetworkManager neu starte.

Das stört mich aber aus 2 Gründen: einerseits kommt es bei meiner Arbeitsweise öfter vor, dass das Handy an- und wieder abgesteckt wird und andererseits würde ich gerne verstehen, was da genau passiert bzw. schief geht und eine saubere Lösung finden.

Smartphone: LG-P700
OS:Debian: 7.3 Codename "Wheezy" mit Gnome Desktop
Architektur: i386

Ergebnisse meiner bisherigen Tests (alle Logauszüge siehe unten):

• in /var/log/messages meldet der kernel bei fehlerhaftem Anschluss "ADDRCONF(NETDEV_UP): usb0: link is not ready"
• die Kernelmodule cdc_acm und cdc_ether gehen aus /var/log/syslog und /var/log/messages hervor
• die Ausgabe von lsusb und lsusb -v ist bei fehlerfreiem und fehlerhaftem Anschluss im wesentlichen identisch
• hwinfo --usb ist auch im wesentlichen identisch
• hwinfo meldet im Eintrag "USB-Link" bei funktionierendem Anschluss "Link detected: yes" und bei fehlerhaftem Anschluss "Link detected: no"
• Die beiden folgenden symbolischen Links werden bei fehlerhaftem wie fehlerfreiem Anschluss angelegt:

  Code: Alles auswählen

  lrwxrwxrwx 1 root root 13 Jan 12 23:11 /dev/serial/by-id/usb-LGE_LG-P700_LGOTMS36b457e-if00 -> ../../ttyACM0
  lrwxrwxrwx 1 root root 13 Jan 12 23:11 /dev/serial/by-path/pci-0000:00:1d.7-usb-0:6:1.0 -> ../../ttyACM0
  

• ebenso die Gerätedatei auf die sie verweisen:

  Code: Alles auswählen

  crw-rw---T 1 root dialout 166, 0 Jan 13 00:16 /dev/ttyACM0
  

Ich gehe also davon aus, dass ein anderer notwendiger Link nicht erstellt wird, wenn das Smarphone bei laufendem NetworkManager angesteckt wird.
Damit bin ich aber am Ende meines Lateins: Alles schön und gut, aber wo erfahre ich denn nun, welcher Link fehlt? Und was hat der NetworkManager überhaupt damit zu tun, da Links doch - wenn ich alles richtig verstehe - über udev angelegt werden? (sorry, aber mit Gerätemanagement kenne ich mich noch gar nicht aus)

Bin für jede Hilfe dankbar,
Luka

Logs:
(Wenn das Smartphone unmittelbar nach dem Hochfahren angeschlossen wurde)

/var/log/messages

Code: Alles auswählen

23:11:27 kernel: [  178.420019] usb 1-6: new high-speed USB device number 4 using ehci_hcd
23:11:27 kernel: [  178.553065] usb 1-6: New USB device found, idVendor=1004, idProduct=91c8
23:11:27 kernel: [  178.553071] usb 1-6: New USB device strings: Mfr=2, Product=3, SerialNumber=4
23:11:27 kernel: [  178.553076] usb 1-6: Product: LG-P700
23:11:27 kernel: [  178.553079] usb 1-6: Manufacturer: LGE
23:11:27 kernel: [  178.553083] usb 1-6: SerialNumber: LGOTMS36b457e
23:11:27 mtp-probe: checking bus 1, device 4: "/sys/devices/pci0000:00/0000:00:1d.7/usb1/1-6"
23:11:27 mtp-probe: bus: 1, device: 4 was not an MTP device
23:11:27 kernel: [  178.622465] Initializing USB Mass Storage driver...
23:11:27 kernel: [  178.622588] scsi4 : usb-storage 1-6:1.0
23:11:27 kernel: [  178.622695] usbcore: registered new interface driver usb-storage
23:11:27 kernel: [  178.622697] USB Mass Storage support registered.
23:11:28 kernel: [  179.620727] scsi 4:0:0:0: CD-ROM            LGE      CDROM storage    0000 PQ: 0 ANSI: 2
23:11:28 kernel: [  179.725088] sr1: scsi-1 drive
23:11:28 kernel: [  179.725945] sr 4:0:0:0: Attached scsi generic sg2 type 5
23:11:28 kernel: [  179.796721] usb 1-6: USB disconnect, device number 4
23:11:29 kernel: [  180.488024] usb 1-6: new high-speed USB device number 5 using ehci_hcd
23:11:29 kernel: [  180.620939] usb 1-6: New USB device found, idVendor=1004, idProduct=61fe
23:11:29 kernel: [  180.620945] usb 1-6: New USB device strings: Mfr=2, Product=3, SerialNumber=4
23:11:29 kernel: [  180.620950] usb 1-6: Product: LG-P700
23:11:29 kernel: [  180.620953] usb 1-6: Manufacturer: LGE
23:11:29 kernel: [  180.620957] usb 1-6: SerialNumber: LGOTMS36b457e
23:11:29 mtp-probe: checking bus 1, device 5: "/sys/devices/pci0000:00/0000:00:1d.7/usb1/1-6"
23:11:29 mtp-probe: bus: 1, device: 5 was not an MTP device
23:11:29 kernel: [  180.689272] cdc_acm 1-6:1.0: ttyACM0: USB ACM device
23:11:29 kernel: [  180.689827] usbcore: registered new interface driver cdc_acm
23:11:29 kernel: [  180.689832] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
23:11:29 kernel: [  180.709932] cdc_ether 1-6:1.3: usb0: register 'cdc_ether' at usb-0000:00:1d.7-6, CDC Ethernet Device, 02:04:53:62:34:35
23:11:29 kernel: [  180.709957] usbcore: registered new interface driver cdc_ether
23:11:29 kernel: [  180.904672] ADDRCONF(NETDEV_UP): usb0: link is not ready
23:12:17 kernel: [  229.012666] ADDRCONF(NETDEV_UP): usb0: link is not ready
23:13:05 kernel: [  277.012654] ADDRCONF(NETDEV_UP): usb0: link is not ready

/var/log/syslog
37604

# lsusb

Code: Alles auswählen

Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 005 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 002 Device 002: ID 046d:c062 Logitech, Inc. LS1 Laser Mouse, corded
Bus 002 Device 003: ID 04f3:0103 Elan Microelectronics Corp. 
Bus 001 Device 005: ID 1004:61fe LG Electronics, Inc. 

# usb-devices
37605

# hwinfo --usb (relevanter Abschnitt)

Code: Alles auswählen

11: USB 00.0: 0000 Unclassified device
  [Created at usb.122]
  Unique ID: MtLc.lY1fqBKlHj2
  Parent ID: k4bc.9T1GDCLyFd9
  SysFS ID: /devices/pci0000:00/0000:00:1d.7/usb1/1-6/1-6:1.0
  SysFS BusID: 1-6:1.0
  Hardware Class: unknown
  Model: "LG Electronics LG-P700"
  Hotplug: USB
  Vendor: usb 0x1004 "LG Electronics, Inc."
  Device: usb 0x61fe "LG-P700"
  Revision: "2.33"
  Serial ID: "LGOTMS36b457e"
  Driver: "cdc_acm"
  Driver Modules: "cdc_acm"
  Speed: 480 Mbps
  Module Alias: "usb:v1004p61FEd0233dcEFdsc02dp01ic02isc02ip01"
  Driver Info #0:
    Driver Status: cdc_acm is active
    Driver Activation Cmd: "modprobe cdc_acm"
  Config Status: cfg=new, avail=yes, need=no, active=unknown
  Attached to: #3 (Hub)

# hwinfo (relevanter Abschnitt)

Code: Alles auswählen

70: None 00.0: 1070c USB-Link
  [Created at net.124]
  Unique ID: IhCv.SyfSGg7YspF
  SysFS ID: /class/net/usb0
  SysFS Device Link: /devices/pci0000:00/0000:00:1d.7/usb1/1-6/1-6:1.3
  Hardware Class: network interface
  Model: "USB-Link network interface"
  Driver: "cdc_ether"
  Driver Modules: "cdc_ether"
  Device File: usb0
  HW Address: 02:04:53:62:34:35
  Link detected: no
  Config Status: cfg=new, avail=yes, need=no, active=unknown

[luka]

Ich habe grad realisiert, dass ich bei meiner Deutung gestern wohl etwas auf dem Holzweg war: Link meint natürlich nicht Sym- oder Hardlink im Dateisystem, sondern data link -> Datenverbindung! Dann kann ich also aufhören, den fehlenden Dateisystemlink zu suchen.
Ansonsten stehe ich aber immer noch auf dem Schlauch ...

[Cae]

Also die naheliegenste Erklaerung waere ja: NetworkManager ist kaputt. Das ist eine allgemein [1] akzeptierte Tatsache, evtl. laesst sich dieser Fall mit spezifischen udev-Skripten besser in den Griff bekommen.

Das "link not ready" koennte darauf schliessen lassen, dass zu kurz auf die Verbindung gewartet wird, aber ich habe keine Idee, wo man dieses Timeout anpassen sollte.

Gruss Cae

[1] (von mir)
Achja, und ein Hinweis darauf steht auch in deinem Log (was uebrigens 37604 ist, dein Link hat da 'n off-by-one):

Code: Alles auswählen

23:11:30 NetworkManager[2788]: nm_system_iface_flush_routes: assertion `ifindex > 0' failed
23:11:30 NetworkManager[2788]: nm_system_iface_flush_addresses: assertion `ifindex > 0' failed

... normalerweise sollten assert()s beim Kompilieren fuer den Produktivbetrieb vorher rausgenommen werden und solche Fehler vom Programmierer behoben sein...

[luka]

Also die naheliegenste Erklaerung waere ja: NetworkManager ist kaputt. Das ist eine allgemein [1] akzeptierte Tatsache, evtl. laesst sich dieser Fall mit spezifischen udev-Skripten besser in den Griff bekommen.

Dann werde ich mich als nächsten Schritt mal mit udev auseinandersetzen. Wenn sich hier jemand damit auskennt, würde ich mich über Unterstützung freuen. Mein Ziel wäre, dass die udev-Regeln die die Module laden, als erstes ein Script starten, mit dem ich den NetworkManager vorrübergehend deaktivere, so wie ich es jetzt manuell tue. Beim Entfernen des Smartphones sollten außerdem die Module cdc_acm und cdc_ether entfernt werden, was jetzt auch per Hand geschehen muss. Bei meinen Versuchen, herauszufinden, was eigentlich passiert, war ich schon auf den Befehl udevadm gestoßen und ich nehme an, dass sich darüber auch herausfinden lässt, welche udev-Regeln zur Anwendung kommen.
Noch sauberer wäre es natürlich, wenn man den NetworkManager einfach dazu bringen könnte, nicht direkt das neue Interface usb0 zu vereinnahmen, wenn es hochkommt, damit erst alle notwendigen Initialisierungen stattfinden können, ehe der NM die Autokonfiguration auslöst, aber ich habe bisher überhaupt keine Hinweise gefunden, dass sich soetwas im NM konfigurieren lässt ...

Das "link not ready" koennte darauf schliessen lassen, dass zu kurz auf die Verbindung gewartet wird, aber ich habe keine Idee, wo man dieses Timeout anpassen sollte.

Ja, ich habe vorhin nochmal die Logs bei funktionierendem und fehlerhaftem Anschluss verglichen, und würd sagen, dass die Deine Einschätzung ziemlich deutlich belegen. Im syslog, das ich hier gepostet hatte, kann man ja sehen, dass mitten in der Autokonfiguration per dhclient, die vom NetworkManager ausgelöst wird, plötzlich der modem-manager versucht, die Schnittstelle /dev/ttyACM0 zu initialisieren, die wie ich inzwischen herausgefunden habe, wohl benötigt wird, damit eine Verbindung zum Gerät hergestellt werden kann. Wird das Smartphone bei gestopptem NM angeschlossen, kommt es zur Initialisierung der Schnittstelle unmittelbar nachdem die Module geladen wurden, so dass beim Start des NM sowohl die Module als auch die initialisierte Schnittstelle bereit stehen.

Werde in den nächsten Tagen wohl nicht dazu kommen, daran weiterzubasteln, aber nächste Woche gehts weiter ...

Gruß,
luka

P.S.:

Achja, und ein Hinweis darauf steht auch in deinem Log (was uebrigens 37604 ist, dein Link hat da 'n off-by-one):

Danke für den Hinweis, hab's korrigiert...

[luka]

So, hat etwas länger gedauert als erwartet. Nun bin ich aber endlich wieder dazu gekommen, mich weiter an einer Lösung zu versuchen.

WORKAROUND - Löst das Problem behelfsmäßig, ohne die Ursachen vollständig aufzulösen:
Per UDEV-Regel wird beim Anschluss des Smartphones ein Script ausgeführt, das den NetworkManager vorübergehend stoppt

Um die Regel zu erstellen, bin ich folgendermaßen vorgegangen:

• Smartphone manuell anstecken (bei gestopptem NetworkManager, damit der modem-manager Zeit hat, die Schnittstelle /dev/ttyACM0 zu initialisieren)
• Attribute des neuen USB-Interface anzeigen mit udevadm -a -p <sysfs-pfad>, in meinem Fall ist der Interface-Name usb0, dementsprechend lautet der Befehl udevadm -a -p /sys/class/net/usb0
• Mit Hilfe der Attributsliste die folgende UDEV-Regel erstellen und in /etc/udev/rules.d ablegen (ich habe als Dateinamen 80-hotplug-networking-special.rules gewählt, der Name ist aber egal, solange er vor 80-networking.rules liegt, das aus /lib/udev/rules.d eingelesen wird und den NetworkManager startet):

  Code: Alles auswählen

  ACTION=="add", SUBSYSTEM=="net", ATTRS{manufacturer}=="LGE", ATTRS{product}=="LG-P700", RUN+="/root/udevscripts/lgp700-nm-handling.sh"
  

  D.h. wenn ein Gerät hinzugefügt wird (ACTION=="add"), das zum SUBSYSTEM net gehört, dessen Hersteller LGE ist und dessen Produktbezeichnung LG-P700, dann wird das Script /root/udevscripts/lgp700-nm-handling.sh ausgeführt.
• a) In der schlichteste Variante des Scripts wird der NetworkManager einfach für einige Sekunden aus dem Verkehr gezogen:

  Code: Alles auswählen

  #!/bin/bash
  /etc/init.d/network-manager stop
  sleep 4
  /etc/init.d/network-manager start 
  

• b) Die komplexere Variante überprüft, ob der modem-manager die nötigen Aktionen zur Initialisierung der Schnittstelle vorgenommen hat, ehe es den NetworkManager wieder startet. Per Timeout wird sichergestellt, dass das Script nicht hängenbleibt, wenn bei der Schnittstelleninitialisierung etwas schief geht, und dass der NetworkManager auf jeden Fall wieder zurückkehrt.

  Code: Alles auswählen

  #!/bin/bash
  timeout=45                      # timeout in Sekunden 
  counter=0                       # Zähler für die syslog-Ereignisse, die 
                                  # stattgefunden haben müssen, ehe wir den 
                                  # NetworkManager wieder starten können
  
  sleep $timeout &                # timeout als Hintergrundprozess laufen 
  timerpid=$!                     # lassen, um tail mit --pid in Abhängigkeit
                                  # von diesem Hintergrundprozess auszuführen
  
  logger -i -p syslog.info "<info> Stopping NetworkManager to enable ttyACM0 initialisation by modem-manager"
  /etc/init.d/network-manager stop
  
  # Gruppierung mit {...} ist erforderlich, um nach der while-Schleife, die 
  # aufgrund der Pipe | als Unterprozess mit eigenen lokalen 
  # Variablen ausgeführt wird, den Wert von $counter auslesen zu können
  
  tail --pid=$timerpid -n0 -f /var/log/syslog | { while read line; do
  
      if [[ "$counter" == "0" && "$line" == *"GSM modem"*"claimed port ttyACM0"* ]]; then
          counter=1
  
      elif [[ "$counter" == "1" && "$line" == *"(ttyACM0) serial port closed"* ]]; then
          counter=2
          pkill -P $$ tail 
      fi
  done
  
  if [[ "$counter" != "2" ]]; then
      logger -i -p syslog.warn "<warn> Reached timeout before modem-manager finished initialisation"
  fi
  }
  
  sleep 2
  
  logger -i -p syslog.info "<info> ttyACM0 initialisation finished. Restarting NetworkManager"
  /etc/init.d/network-manager start
  

Fazit: Kann nicht behaupten, dass ich mit UDEV wirklich warm geworden wäre. Die Dokumentation fand nicht sonderlich hilfreich, jedenfalls für den Einstieg. Sehr geholfen hat mir hingegen das Howto Writing udev rules (englisch)

[luka]

Wie man sieht, musste ich auch beim 2. Script nach der Schnittstelleninitialisierung durch den modem-manager vor dem Start des NetworkManagers immer noch 2 Sekunden Wartezeit einbauen.
Wird der NetworkManager nämlich ohne weitere Pause unmittelbar nach der Initialisierung der Schnittstelle gestartet, so meldet der Kernel in /var/log/syslog: kernel: [60503.243611] ADDRCONF(NETDEV_UP): usb0: link is not ready (gemeint ist zu diesem Zeitpunkt wohl der Hardware-Link zwischen PC-Schnittstelle usb0 und dem Smartphone, also sozusagen "Kabel nicht angeschlossen", was natürlich unfug ist). Ärgerlicherweise scheint das auch zunächst nur der Kernel so zu sehen, da die Schnittstelle usb0 zu diesem Zeitpunkt bereits vorhanden ist und sich innerhalb der Wartezeit auch auf up schalten lässt (getestet via ifconfig), so dass der NetworkManager, vom Kernel-Einwand gänzlich unbeeindruckt, stumpf mit der IP-Konfiguration fortfährt (ifup verhält sich an dieser Stelle übrigens identisch, habe ich ebenfalls getestet).

Trotz intensiver Suche in /var/log/* und Tests mit udevadm monitor habe ich keinerlei Hinweise finden können, wozu diese Zeit benötigt wird; "(ttyACM0) serial port closed" ist bei gestopptem NetworkManager die letzte Meldung in den Logdateien und auch die UDEV-Warteschlange ist zum Zeitpunkt dieser Meldung bereits abgearbeitet.

Hat noch jmd. eine Idee, wozu die 1.5 Sekunden benötigt werden oder wie ich dem noch auf die Spur kommen könnte?
Würde mich sehr über Reaktionen freuen, sehe aber ein, dass das Problem ziemlich speziell ist. Wenn nichts mehr kommt, würde ich das hier in ein paar Tagen auf "gelöst" setzen. Ist es ja im Sinne der ursprünglichen Fragestellung auch, obwohl nicht alles aufgeklärt werden konnte und die ereignisunabhängigen Timeouts von 4 bzw. 2 Sekunden bei sehr hoher Prozessorlast wahrscheinlich nicht zuverlässig sind.

Oh, und hat jmd. 'ne Ahnung, wo der Bugreport hingehört? Wer schreibt denn die udev-Regeln für Smartphones? Das Team vom NetworkManager?