Linux cdc_acm device - caracteres inesperados enviados para o dispositivo USB

Navegue suas respostas
3

Estou tendo problemas com caracteres inesperados sendo enviados em uma porta USB com o driver cdc_acm. O que torna isso ainda mais desconcertante é que o código roda no Ubuntu 12.04 (kernel 3.2), mas falha (o assunto desta questão) no Centos 6 (kernel 3.6).

O dispositivo USB é um dongle Bluegiga BLED112 Bluetooth Smart. Seu microcontrolador embutido será reinicializado a qualquer momento em uma entrada inesperada em sua interface USB.

O código de teste abre a porta, grava 4 bytes (uma mensagem de saudação) e espera ler uma resposta. A leitura nunca é concluída porque os caracteres inesperados fazem com que o dispositivo seja redefinido, o que faz com que o hub solte o dispositivo e renumere.

Para resolver o problema, eis o que fiz:

  • Baixou o código fonte do driver cdc_acm. Adicionado um monte de mensagens de depuração printk e stack_dumps para acompanhar o que está acontecendo.
  • Eu rmmod'd o "estoque" cdc_acm e insmod'd meu módulo instrumentado. Toda a enumeração de dispositivos funciona, driver correto anexado, etc.
  • Como o código funciona no Ubuntu 12.04 / Linux 3.2, peguei o código 3.2 cdc_acm e o compilei na plataforma CentOS 6 / Linux 3.6. O uso desse módulo 3.2 em vez do módulo 3.6 não fez diferença. Voltei ao módulo 3.6.
  • Ligou o sistema de arquivos de depuração com usbmon e observou o tráfego USB. Eu posso ver que há caracteres extras sendo enviados na interface USB.
  • Para observar o que está acontecendo, no topo do printk no módulo cdc_acm, mesclei a saída de usb mon (cat / sys / kernel / debug / usb / usbmon / 3u | logger) e a saída do aplicativo de teste (scan_example / dev / ttyACM0 | logger -s), portanto, tenho um fluxo único de rastreio de depuração correlacionado por tempo.
  • Os caracteres espúrios enviados no endpoint USB são x5E x40 x5E x40 x5E x40 x5E x40 x41 (em ASCII é o seu ^ @ ^ @ ^ @ ^ A) que se parece com algum tipo de sondagem ou tentando chamar a atenção de um modem Esses caracteres são enviados imediatamente depois que o write () do aplicativo faz com que os 4 bytes hello sejam enviados para o ponto final.

  • Como o dispositivo cdc_acm deve ser um modem, tentei desligar o controle do modem adicionando isso ao usb_device_id acm_ids [] em cdc_acm.c 

    /* bluegiga BLED112*/
{ USB_DEVICE(0x2458, 0x0001),
.driver_info = NOT_A_MODEM,
},

  • Recompilados e insmod'd e o syslog mostram que isso foi reconhecido (quirks é 8), mas nenhuma mudança na função.

Nem o NetowrkManager nem o modem-manager estão rodando, mas eu ainda suspeito que há algum tipo de função de controle de modem acontecendo em algum lugar, eu simplesmente não sei onde.

Aqui está um registro de depuração anotado (o MDV prefixa aqueles printk's que eu adicionei ao cdc_acm) 

Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_bulk
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_done

Aqui estão os 4 bytes enviados pelo aplicativo 00 00 00 01 

Feb 13 18:14:32 localhost cpcenter: df046a80 3672670191 C Bi:3:006:4 0 4 = 00000001
Feb 13 18:14:32 localhost cpcenter: 1360797272.669690 write: data2: len=0 contains:

... e estes caracteres adicionais aparecem inesperadamente 5e 40 5e 40 5e 40 .... 

Feb 13 18:14:32 localhost cpcenter: df046a80 3672670232 S Bi:3:006:4 -115 128 <
Feb 13 18:14:32 localhost cpcenter: f3cc5740 3672670297 S Bo:3:006:4 -115 1 = 5e
Feb 13 18:14:32 localhost cpcenter: df2e1300 3672670332 S Bo:3:006:4 -115 1 = 40
Feb 13 18:14:32 localhost cpcenter: f3cc5740 3672670347 C Bo:3:006:4 0 1 >
Feb 13 18:14:32 localhost cpcenter: f3cc5740 3672670392 S Bo:3:006:4 -115 1 = 5e
Feb 13 18:14:32 localhost cpcenter: df2e1180 3672670426 S Bo:3:006:4 -115 1 = 40
Feb 13 18:14:32 localhost cpcenter: df2e1c00 3672670461 S Bo:3:006:4 -115 1 = 5e
Feb 13 18:14:32 localhost cpcenter: df2e1840 3672670496 S Bo:3:006:4 -115 1 = 40
Feb 13 18:14:32 localhost cpcenter: df2e1300 3672670591 C Bo:3:006:4 0 1 >

Neste ponto, temos uma desconexão espontânea. 

Feb 13 18:14:32 localhost kernel: usb 3-1: USB disconnect, device number 6
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_bulk
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_done
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm read_bulk_callback
Feb 13 18:14:32 localhost kernel: MDV 1 acm_read_bulk_callback - urb 1, len 0
Feb 13 18:14:32 localhost kernel: MDV 3 acm_read_bulk_callback - non-zero urb status: -71
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_bulk
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_done
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm read_bulk_callback
Feb 13 18:14:32 localhost kernel: MDV 1 acm_read_bulk_callback - urb 1, len 0
Feb 13 18:14:32 localhost kernel: MDV 3 acm_read_bulk_callback - non-zero urb status: -71
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_bulk
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_done
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm read_bulk_callback
Feb 13 18:14:32 localhost kernel: MDV 1 acm_read_bulk_callback - urb 2, len 0
Feb 13 18:14:32 localhost cpcenter: df2e1d80 3672670629 S Bo:3:006:4 -115 1 = 5e
Feb 13 18:14:32 localhost kernel: MDV 3 acm_read_bulk_callback - non-zero urb status: -71
Feb 13 18:14:32 localhost cpcenter: df2e1300 3672670677 S Bo:3:006:4 -115 1 = 41
Feb 13 18:14:32 localhost cpcenter: f3cc5740 3672670802 C Bo:3:006:4 0 1 >
Feb 13 18:14:32 localhost cpcenter: df2e1180 3672671019 C Bo:3:006:4 0 1 >
Feb 13 18:14:32 localhost cpcenter: df2e1c00 3672671237 C Bo:3:006:4 0 1 >
Feb 13 18:14:32 localhost cpcenter: dfbf8c00 3672673193 C Ii:3:001:1 0:2048 1 = 02
Feb 13 18:14:32 localhost cpcenter: dfbf8c00 3672673207 S Ii:3:001:1 -115:2048 4 <
Feb 13 18:14:32 localhost cpcenter: f3c26c00 3672673221 S Ci:3:001:0 s a3 00 0000 0001 0004 4 <
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_disconnect
Feb 13 18:14:32 localhost kernel: Pid: 29, comm: khubd Tainted: G           O 3.5.3-1.el6.elrepo.i686 #1

Rastreamento de pilha no momento da desconexão 

Feb 13 18:14:32 localhost kernel: Call Trace:
Feb 13 18:14:32 localhost kernel: [<f82dabc5>] acm_disconnect+0x35/0x1f0 [cdc_acm]
Feb 13 18:14:32 localhost kernel: [<c13835db>] usb_unbind_interface+0x4b/0x180
Feb 13 18:14:32 localhost cpcenter: f3c26c00 3672673239 C Ci:3:001:0 0 4 = 00010100
Feb 13 18:14:32 localhost kernel: [<c1318bfb>] __device_release_driver+0x5b/0xb0
Feb 13 18:14:32 localhost kernel: [<c1318d05>] device_release_driver+0x25/0x40
Feb 13 18:14:32 localhost kernel: [<c1317f0c>] bus_remove_device+0xcc/0x130
Feb 13 18:14:32 localhost kernel: [<c131612f>] ? device_remove_attrs+0x2f/0x90
Feb 13 18:14:32 localhost kernel: [<c1316275>] device_del+0xe5/0x180
Feb 13 18:14:32 localhost kernel: [<c1380326>] usb_disable_device+0x96/0x240    Feb 13 18:14:32 localhost kernel: [<c1379f91>] usb_disconnect+0x91/0x130
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_bulk
Feb 13 18:14:32 localhost kernel: [<c137a2c0>] hub_port_connect_change+0xb0/0xa60
Feb 13 18:14:32 localhost kernel: [<c1380f4e>] ? usb_control_msg+0xce/0xe0
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm acm_write_done
Feb 13 18:14:32 localhost kernel: [<c137b296>] hub_events+0x536/0x810
Feb 13 18:14:32 localhost cpcenter: f3c26c00 3672673243 S Co:3:001:0 s 23 01 0010 0001 0000 0
Feb 13 18:14:32 localhost cpcenter: f3c26c00 3672673250 C Co:3:001:0 0 0
Feb 13 18:14:32 localhost kernel: [<c1065bdf>] ? finish_wait+0x4f/0x70
Feb 13 18:14:32 localhost kernel: [<c137b5aa>] hub_thread+0x3a/0x1d0
Feb 13 18:14:32 localhost cpcenter: df2e1840 3672673260 C Bo:3:006:4 -71 0
Feb 13 18:14:32 localhost kernel: [<c1065a70>] ? wake_up_bit+0x30/0x30
Feb 13 18:14:32 localhost kernel: [<c137b570>] ? hub_events+0x810/0x810
Feb 13 18:14:32 localhost kernel: [<c106564c>] kthread+0x7c/0x90
Feb 13 18:14:32 localhost cpcenter: f3c16c80 3672673292 C Bi:3:006:4 -71 0
Feb 13 18:14:32 localhost cpcenter: df2e1d80 3672673453 C Bo:3:006:4 -71 0
Feb 13 18:14:32 localhost cpcenter: f3c16d40 3672673553 C Bi:3:006:4 -71 0
Feb 13 18:14:32 localhost kernel: [<c10655d0>] ? kthread_freezable_should_stop+0x60/0x60
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm read_bulk_callback
Feb 13 18:14:32 localhost kernel: [<c14dedbe>] kernel_thread_helper+0x6/0x10
Feb 13 18:14:32 localhost kernel: MDV 1 acm_read_bulk_callback - urb 3, len 0
Feb 13 18:14:32 localhost kernel: MDV:cdc-acm stop_data_traffic
Feb 13 18:14:32 localhost cpcenter: f3d19500 3672674474 C Ii:3:006:2 -108:64 0
Feb 13 18:14:32 localhost kernel: MDV 2 acm_read_bulk_callback - disconnected
Feb 13 18:14:32 localhost cpcenter: df2e1300 3672674636 C Bo:3:006:4 -71 0
Feb 13 18:14:32 localhost cpcenter: f3c16140 3672674753 C Bi:3:006:4 -71 0
    
por MikeV 14.02.2013 / 08:52

1 resposta

2

Depois de adicionar mais rastreios do kernel, encontrei 

localhost kernel: [<c12c6757>] process_echoes+0x117/0x2c0
localhost kernel: [<c12c8409>] n_tty_receive_char+0x379/0x770
localhost kernel: [<c121fce4>] ? rb_erase+0xb4/0x120 
localhost kernel: [<c12c89f6>] n_tty_receive_buf+0x1f6/0x380 
localhost kernel: [<c14d62cb>] ? __schedule+0x39b/0x6d0

que mostra o subsistema tty ecoando e apagando caracteres - esses eram os caracteres que estavam causando o problema. O código a seguir remove a disciplina de linha tty e agora funciona 

struct termios usb_termio; // set the USB to raw mode
memset(&usb_termio, 0, sizeof(usb_termio)); // clear the structure 
cfmakeraw(&usb_termio); 
if (tcsetattr(BLED_fd, TCSANOW, &usb_termio)< 0) {
    perror("tcsetattr usb");
    return(1);
}

@Sergey Vlasov no Stack Overflow analisou o traço da mensagem USB e chegou à mesma conclusão de outro caminho. Sua explicação me ajudou a entender melhor a saída usbmon link

    
por 18.04.2013 / 16:34

Tags

tshark dump somente quando a string é correspondida Instâncias duplicadas no menu do Gnome