Dotaz: OpenWRT, TL-MR3220 v2, AnyDATA ADU-510L: modem hangup po 2 minutách

[bhy]

Dobré odpoledne všem,

používám OpenWRT 14.07 Barrier Breaker na routeru TP-LINK TL-MR3220 v2 s 3G USB modemem AnyDATA ADU-510L od U:fona jakožto jediným spojením ven. OpenWRT jsem na router dal proto, že stock firmware můj modem vůbec nepodporoval (psal "connecting.." ale nikdy se nepřipojil, a LEDka na modemu svítila zeleně, při připojování má svítit modře).

Teď se můžu úspěšně připojit, download i upload funguje normální rychlostí atd., ale spojení se vždy přeruší zhruba za 2 minuty. Často se doporučuje nastavit pppd option "noipdefault", což jsem udělal, ale nemělo to na nic vliv.

Může jít o problém s napájením, související s tímhle: https://forum.openwrt.org/viewtopic.php?id=39956
A může tedy být nutné, abych mezi router a modem přidal USB hub.
Jde ale o jiný typ desky, můj router je ar71xx. Instaloval jsem z image openwrt-ar71xx-generic-tl-mr3220-v2-squashfs-factory.bin
Nemám možnost změřit napětí v USB portu routeru.

Zde je výstup logread:

Wed Nov 12 13:31:20 2014 local2.info chat[5740]: abort on (BUSY)
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: abort on (NO CARRIER)
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: abort on (ERROR)
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: abort on (NO DIAL TONE)
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: abort on (NO ANSWER)
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: abort on (DELAYED)
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: report (CONNECT)
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: timeout set to 10 seconds
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: send (AT^M)
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: expect (OK)
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: AT^M^M
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: OK
Wed Nov 12 13:31:20 2014 local2.info chat[5740]:  -- got it
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: send (ATZ^M)
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: timeout set to 30 seconds
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: expect (OK)
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: ^M
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: ATZ^M^M
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: OK
Wed Nov 12 13:31:20 2014 local2.info chat[5740]:  -- got it
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: send (ATDT#777^M)
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: expect (CONNECT)
Wed Nov 12 13:31:20 2014 local2.info chat[5740]: ^M
Wed Nov 12 13:31:21 2014 local2.info chat[5740]: ATDT#777^M^M
Wed Nov 12 13:31:21 2014 local2.info chat[5740]: CONNECT
Wed Nov 12 13:31:21 2014 local2.info chat[5740]:  -- got it
Wed Nov 12 13:31:21 2014 local2.info chat[5740]: send (^M)
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: Script DIALNUMBER= /usr/sbin/chat -t5 -v -E -f /etc/chatscripts/evdo.chat finished (pid 5739), status = 0x0
Wed Nov 12 13:31:21 2014 daemon.info pppd[1126]: Serial connection established.
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: using channel 36
Wed Nov 12 13:31:21 2014 daemon.info pppd[1126]: Using interface 3g-3g
Wed Nov 12 13:31:21 2014 daemon.notice pppd[1126]: Connect: 3g-3g <--> /dev/ttyUSB0
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: rcvd [LCP ConfReq id=0x1     ]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: sent [LCP ConfReq id=0x24  ]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: sent [LCP ConfRej id=0x1  ]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: rcvd [LCP ConfAck id=0x24  ]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: rcvd [LCP ConfReq id=0x2   ]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: sent [LCP ConfAck id=0x2   ]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: sent [LCP EchoReq id=0x0 magic=0x10cd98eb]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: rcvd [CHAP Challenge id=0x1 , name = ""]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: sent [CHAP Response id=0x1 <25da9f0d22715c939e85c456cc575fc4>, name = "ufon"]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: rcvd [CHAP Success id=0x1 ""]
Wed Nov 12 13:31:21 2014 daemon.info pppd[1126]: CHAP authentication succeeded
Wed Nov 12 13:31:21 2014 daemon.notice pppd[1126]: CHAP authentication succeeded
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: sent [IPCP ConfReq id=0x47   ]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: sent [IPV6CP ConfReq id=0x24 ]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: rcvd [IPCP ConfReq id=0x1 ]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: sent [IPCP ConfAck id=0x1 ]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: rcvd [IPCP ConfNak id=0x47   ]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: sent [IPCP ConfReq id=0x48   ]
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: rcvd [IPCP ConfAck id=0x48   ]
Wed Nov 12 13:31:21 2014 daemon.notice netifd: Network device '3g-3g' link is up
Wed Nov 12 13:31:21 2014 daemon.notice pppd[1126]: local  IP address 78.136.147.93
Wed Nov 12 13:31:21 2014 daemon.notice pppd[1126]: remote IP address 172.18.55.1
Wed Nov 12 13:31:21 2014 daemon.notice pppd[1126]: primary   DNS address 78.136.128.4
Wed Nov 12 13:31:21 2014 daemon.notice pppd[1126]: secondary DNS address 78.136.128.12
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: Script /lib/netifd/ppp-up started (pid 5767)
Wed Nov 12 13:31:21 2014 daemon.notice netifd: Interface '3g' is now up
Wed Nov 12 13:31:21 2014 daemon.debug pppd[1126]: Script /lib/netifd/ppp-up finished (pid 5767), status = 0x1
Wed Nov 12 13:31:21 2014 user.notice firewall: Reloading firewall due to ifup of 3g (3g-3g)
Wed Nov 12 13:31:24 2014 daemon.debug pppd[1126]: sent [IPV6CP ConfReq id=0x24 ]
Wed Nov 12 13:31:27 2014 daemon.debug pppd[1126]: sent [IPV6CP ConfReq id=0x24 ]
Wed Nov 12 13:31:30 2014 daemon.debug pppd[1126]: sent [IPV6CP ConfReq id=0x24 ]
Wed Nov 12 13:31:33 2014 daemon.debug pppd[1126]: sent [IPV6CP ConfReq id=0x24 ]
Wed Nov 12 13:31:36 2014 daemon.debug pppd[1126]: sent [IPV6CP ConfReq id=0x24 ]
Wed Nov 12 13:31:38 2014 daemon.info dnsmasq[1198]: reading /tmp/resolv.conf.auto
Wed Nov 12 13:31:38 2014 daemon.info dnsmasq[1198]: using local addresses only for domain lan
Wed Nov 12 13:31:38 2014 daemon.info dnsmasq[1198]: using nameserver 78.136.128.4#53
Wed Nov 12 13:31:38 2014 daemon.info dnsmasq[1198]: using nameserver 78.136.128.12#53
Wed Nov 12 13:31:39 2014 daemon.debug pppd[1126]: sent [IPV6CP ConfReq id=0x24 ]
Wed Nov 12 13:31:42 2014 daemon.debug pppd[1126]: sent [IPV6CP ConfReq id=0x24 ]
Wed Nov 12 13:31:45 2014 daemon.debug pppd[1126]: sent [IPV6CP ConfReq id=0x24 ]
Wed Nov 12 13:31:48 2014 daemon.debug pppd[1126]: sent [IPV6CP ConfReq id=0x24 ]
Wed Nov 12 13:31:51 2014 daemon.warn pppd[1126]: IPV6CP: timeout sending Config-Requests
Wed Nov 12 13:33:02 2014 daemon.debug pppd[1126]: rcvd [LCP TermReq id=0x3]
Wed Nov 12 13:33:02 2014 daemon.info pppd[1126]: LCP terminated by peer
Wed Nov 12 13:33:02 2014 daemon.info pppd[1126]: Connect time 1.7 minutes.
Wed Nov 12 13:33:02 2014 daemon.info pppd[1126]: Sent 44136 bytes, received 99893 bytes.
Wed Nov 12 13:33:02 2014 daemon.notice netifd: Network device '3g-3g' link is down
Wed Nov 12 13:33:02 2014 daemon.debug pppd[1126]: Script /lib/netifd/ppp-down started (pid 5892)
Wed Nov 12 13:33:02 2014 daemon.debug pppd[1126]: sent [LCP TermAck id=0x3]
Wed Nov 12 13:33:02 2014 daemon.notice netifd: Interface '3g' has lost the connection
Wed Nov 12 13:33:02 2014 daemon.debug pppd[1126]: Script /lib/netifd/ppp-down finished (pid 5892), status = 0x1
Wed Nov 12 13:33:05 2014 daemon.debug pppd[1126]: rcvd [LCP TermReq id=0x4]
Wed Nov 12 13:33:05 2014 daemon.debug pppd[1126]: sent [LCP TermAck id=0x4]
Wed Nov 12 13:33:05 2014 daemon.notice pppd[1126]: Connection terminated.
Wed Nov 12 13:33:05 2014 kern.err kernel: [ 4934.170000] option1 ttyUSB0: option_instat_callback: error -2
Wed Nov 12 13:33:06 2014 daemon.notice pppd[1126]: Modem hangup
Wed Nov 12 13:33:26 2014 daemon.warn dnsmasq[1198]: no servers found in /tmp/resolv.conf.auto, will retry

Po ukončení spojení se modem za několik sekund znova připojí (sám od sebe, bez mého zásahu) a celý scénář se opakuje.

Zvláštní je, že se to děje velmi pravidelně, podle dmesg každých 137 sekund (možná 2 minuty uptime + 17 sekund připojování?):

[ 4112.150000] option1 ttyUSB0: option_instat_callback: error -2
[ 4249.110000] option1 ttyUSB0: option_instat_callback: error -2
[ 4386.200000] option1 ttyUSB0: option_instat_callback: error -2
[ 4523.160000] option1 ttyUSB0: option_instat_callback: error -2
[ 4660.250000] option1 ttyUSB0: option_instat_callback: error -2
[ 4797.210000] option1 ttyUSB0: option_instat_callback: error -2
[ 4934.170000] option1 ttyUSB0: option_instat_callback: error -2
[ 5071.260000] option1 ttyUSB0: option_instat_callback: error -2
[ 5208.090000] option1 ttyUSB0: option_instat_callback: error -2

atd.

Vzhledem k té pravidělnosti si nejsem jist, zda jde skutečně o problém s napájením.
Myslíte, že si mám pořídit ten USB hub, nebo to může být něčím úplně jiným?

díky moc
bhy

Odpovědi

[R]

Nic nekupuj, je to bug v kerneli:

https://dev.openwrt.org/ticket/17984

http://www.spinics.net/lists/linux-usb/msg111248.html

[bhy]

díky, na to jsem už koukal, ale mám dojem, že to je jiná chyba, protože dotyčný píše, že mu modem normálně funguje (pochopil jsem to tak, že nepřetržitě) a jeho problémem je množství hlášek v logu (které jsou u něj mnohem častější než u mě).

[R]

Aha, ano. Blbo som to precital, je to len falosne chybove hlasenie.

[frr]

No já vidím v modemovém logu PPP frame LCP TERM REQ od modemu. Modem košer požádá o ukončení relace. PPP relaci v případě GPRS a spol. servíruje lokální GSM modem, který ji překlápí na GTP v rámci GSM stacku. Těžko říct, jestli to položí svévolně modem, nebo jestli mu to nakuká síť. Zkuste přidat do nějakého skriptu rozpoutání pravidelného pingu někam ven do internetu. Nemusí to pingat moc často, třeba jednou za pár desítek vteřin by mohlo stačit.

Marketový multimetr stojí 2-3 stovky a je užitečný opakovaně, doporučuji koupit. Lepší by byl osciloskop, ale to už je otázka pár pár tisíc za základní USB model.

Pokud máte podezření na napájení, nepotřebujete ani hub (stejně ty levné často nepodporují externí napájecí vstup), stačí rozpárat USB prodlužovák a napájení přivést natvrdo na červený proti černému. Nebo si zbastlit napájecí vsuvku ze dvou konektorů (samec+samice). Jako napájecí zdroj doporučuji spínaný adaptér cca 5V/3A, který se dá koupit jako náhradní k WiFi APčkům (Aspa) nebo v bastlířských krámech. Vzhledem k tomu, že potřebujete taky multimetr, možná dutý konektor a možná trafopáječku (a cín a kalafunu a smršťovací bužírky), doporučuju jako vhodnou hračkárnu GME nebo TME. Užitečná bastlo-hračka je taky pistole na tavné lepidlo.

[bhy]

Ha, díky za nakopnutí.
Když nechám běžet ping, spojení skutečně vydrží déle (zkoušel jsem asi 25 minut). Je to ale bohužel k ničemu, protože když se pak (později než 2 minuty od připojení) pokusím o navázání jakéhokoliv http spojení, modem se zase zavěsí.
Nicméně nabourává to trochu teorii o nízkém napájení (snad jedině že by modem měl při pingu nižší spotřebu než při http spojení). Uvidíme.

[R]

Problemy s napajanim vacsinou vyzeraju inak - USB zariadenie sa resetuje, vyzera to ako odpojenie a znovu pripojenie k USB portu.

Skus to pripojit k normalnemu PC s Linuxom a spustit pppd s rovnakymi parametrami.

[frr]

Ještě dotaz: když to spojení normálně používáte = surfujete a tak, nebo běží nějaký přenos dat... tak to stejně po 2 minutách padne? *to* by bylo divné... pak by to totiž nebyl "idle timeout".

Jsou to přesně dvě minuty? Nebo "řádově tak nějak přibližně"?

Nemáte nakonec jenom problém s kvalitou příjmu? Pokud se ten modem baví přes AT příkazy, co řekne třeba na AT+CSQ ?

[bhy]

ano, spojení padne i když se zrovna v tu chvíli načítá stránka nebo stahují data.
v dmesg na routeru je chyba usb vždycky jednou za 137 sekund:

[ 4112.150000] option1 ttyUSB0: option_instat_callback: error -2
[ 4249.110000] option1 ttyUSB0: option_instat_callback: error -2
[ 4386.200000] option1 ttyUSB0: option_instat_callback: error -2
[ 4523.160000] option1 ttyUSB0: option_instat_callback: error -2
[ 4660.250000] option1 ttyUSB0: option_instat_callback: error -2
[ 4797.210000] option1 ttyUSB0: option_instat_callback: error -2

atd.

AT+CSQ vyzkouším, až budu u routeru.

[frr]

Jak už výše odpověděl R, patrně to velmi dobře shrnuje OpenWRT ticket 17984. Podle toho co v tom ticketu píšou, ta hláška nemusí nutně znamenat selhání, možná je to jenom chybná interpretace nějakého result kódu, cosi vytištěného v logu co nemusí mít vliv na reálné fungování. Konkrétně tam tuším zmiňovali, že jakýsi takový check přesunuli do device open()/close(), což by mohlo korelovat s okamžiky, kdy pppd v reakci na TERM REQ (a následný TEERM ACK) košer zavře a znovu otevře /dev/ttyUSB0.

=> zkuste stopnout pppd a zeptat se minicomem (nebo čím) přímo modemu na AT+CSQ. Je fakt, že nemám referenční hodnoty pro Váš modem...

Myslím si správně, že ten krám má pouze zabudovanou anténku, bez možnosti připojit externí? Kde je to celé umístěno? Je to pohromadě s další počítačovou technologií, nebo relativně "volně v prostoru"? Je to USB dongle - připadalo by v úvahu, koupit 2m-5m USB prodlužovák a samotný USB modem vystrčit třeba jenom experimentálně na pár minut z okna? Taky by se třeba dalo to pouzdro lousknout a přiletovat tenký pigtail pro připojení externí antény. Možná by základní čtvrtvlnný pahýl na 450 MHz "hrál" líp než miniaturní a zkrácená anténa na plošáku toho donglu.

Moderní okna s determálními skly (= všechna plastová) dost tlumí cokoli od dlouhých vln přes televizní pásmo, GSM až po wifi v obou pásmech. Resp. pokovená skla zhorší odstup lokálních rušení uvnitř budovy.

Zažili jsme v práci, že nám dost zlobily mobily. Padaly GSM relace, přitom signál relativně slušný (aspoň podle čárek). Jako jednu z hypotéz jsme se doslechli, že to může být v místě na rozhraní mezi dvěma GSM buňkami, kde dochází k náhodnému handoveru z jedné buňky na druhou podle lokálních anomálií v síle pole uvnitř budovy... Časem ten problém polevil, bez nějakého našeho přičinění.

Anebo je možné, že je to fakt bug ve firmwaru toho modemu. Střeva jsou údajně nějaký Qualcomm, to není špatnej oddíl - spíš je otázkou, zda se do toho třeba vůbec dá sehnat aktualizace firmwaru. Dost pochybuju Bude to nějaká speciální ufoní edice - i pokud byste zjistil, že se to venku prodává pod jinými názvy, nemusel by nějaký "generický" nebo "cizí" firmware proti ufoní síti správně fungovat... Navíc ten produkt je patrně už dost starý... možná byste mohl zkusit Ufona nebo Anydata požádat o aktuální firmware, ale moc šancí tomu nedávám

Jestli si s tím modemem popovídáte přes AT příkazy, zkuste se ho zeptat ještě na ATI nebo ATI3 (obecně ATI0, ATI1, ATI2 atd.) Zjištěné informace o verzi firmwaru by se mohly hodit při případné komunikaci s výrobcem či Ufonem.

Zkoušel jste ten modem pod Vindózama? Jede to furt?

[bhy]

Díky moc:)

Modem byl předtím připojen v podstatě v témže místě přímo k počítači (s Fedorou, naštěstí Windows tu nemáme resp. nemusíme je používat) a tam nebyly žádné problémy, sílu signálu to ukazovalo nízkou ale spojení nevypadávalo.

Po připojení k aktivnímu hubu se sice nic nezměnilo, ale díky prodlužováku od hubu je možné modem umístit blíž oknu, taky se nic nezměnilo, a nezměnilo se ani při provozu s otevřeným oknem. Přímou souvilost se silou signálu jsem prozatím vyloučil.

Po troše googlení jsem na základě diskuzí na ruských a rumunských webech:) přidal do /etc/config/network

option ppp_redial 'persist'
option keepalive '10 20'

čímž se doba trvání spojení před pádem prodloužila na cca 10-12 minut a hlavně zmizely prodlevy mezi hangupem a opětovným vytáčením (ty 2 minuty předtím tam byly asi z OpenWRTího cronu, je to čas po kterém se obnovuje padlé spojení).

Dál jsem pak přemýšlel, proč předtím při pingu spojení vydrželo déle než ty 2 minuty a napadla mě souvislost s velikostí MTU (ping má malé frames, nebo jak se to jmenuje). ifconfig ukázal, že je nastaveno na 1500, což pro mobilní síť asi není to pravé ořechové. Snížil jsem ho na 1300 a spojení nyní vydrží cca 25-30 minut (a okamžitě se obnoví), což už je mnohem použitelnější.

option mtu '1300'

Příští týden vyzkouším, jestli se to ještě zlepší při dalším snížení MTU.

Díky za rady.

[frr]

No vida Vyřešil jste si to sám...

Spojitost s MTU je mi záhadou, ale co už.

PPP keepalives... hezky

[frr]

BTW ještě k tomu napájecímu prodlužováku... zem (černý) musí zůstat průchozí i v původním směru, +5V (červený) propojit z přídavného zdroje jenom do periferního zařízení = od počítače ustřihnout.