Dotaz: PySerial, Bad file descriptor

[Dadam]

Přes /dev/ttyUSB1 komunikuju s vestavěným zařízením. Jednak skriptem napsaným v Pythonu, jednak programátorem, který pracuje "normálně" (pošle znak @ ať si zařízení odvodí rychlost, přečte odpověď, potom pošle program), nic s časováním nebo podobnými hrůzami.

Problém je, že když spustím skript, který proběhne v pořádku, mi další použití programátoru selže při čtení odpovědi s chybou Failed: Bad file descriptor. Toto se děje až do restartu počítače, nepomůže ani odpojení zařízení (svůj zdroj energie nemá). Jediné co pomůže je před programováním otevřít port v Cutecomu, naprogramovat zařízení, Cutecom zavřít.

Pokud Cutecom nezavřu, příští pokus o naprogramování zase končí chybou (pokud mezitím spustím skript). Pokud Cutecom zavřu před naprogramováním, nemá jeho otevření žádný efekt.

Co s tím? Jaké mi může PySerial přenastavit port (v zařízení je FT2232) tak, že nepomůže ani odpojení?

---

---

Odpovědi

[Pavel Stárek]

A ten skript v Pythonu by nebyl k nahlédnutí? PySerial pod linuxem používám celkem běžně, a nikdy jsem nepozoroval nějaké podezřelé chování.

[Dadam]

Zde je skript:

#!/usr/bin/python2

from PIL import Image
import PIL
import serial
import string
import time
import re
import sys

sizeR = re.compile(r"w(?P<width>\d\d\d)h(?P<height>\d\d\d)")

print "Opening image..."
img = Image.open(sys.argv[2])
img = img.convert("L").transpose(Image.FLIP_TOP_BOTTOM);
size = "w%03dh%03d" % (img.size[0], img.size[1])
size_i = img.size
img = img.tostring()

print "Transmitting image..."
#vepa = serial.Serial(sys.argv[1], 230400, timeout=5)
vepa = serial.Serial(sys.argv[1], 921600, timeout=15)
vepa.write(size)

time.sleep(0.1)

written = 0
while (written < len(img)):
	written += vepa.write(img[written:])

print "Receiving image..."

main_prof_time = vepa.readline()
prof_time = vepa.readline()

size = vepa.read(8)
if (len(size) != 8):
	print "size too short"
	quit(1)
result = sizeR.search(size)
if (not result):
	print "corrupted size: " + `size`
	quit(1)
size = (int(result.group("width")), int(result.group("height")))


img = vepa.read(size[0]*size[1])
if (len(img) != size[0]*size[1]):
	print "corrupted data: only " + `len(img)` + " bytes"
	quit(1)
print "Processing time: "+ main_prof_time[:-1]
print "Processing time: "+ prof_time[:-1]
print "Saving processed image..."
img = Image.fromstring("L", size, img).transpose(Image.FLIP_TOP_BOTTOM)
img = img.convert("RGB")
img.save(sys.argv[3])
print "Done."

Na začátku se otevře a zpracuje bitmapa, odešle se velikost, 100ms čeká (pozůstatek z doby kdy mi zařízení běželo tak nějak pomalu), pak odešle celou bitmapu. Přijme údaje profilové analýzy, přijme velikost nové bitmapy, přijme data bitmapy a uloží ji.

[Pavel Stárek]

Takže abych si to ujasnil. Po zapnutí PC a spuštění tohoto skriptu tento skript poprvé projde. Pokud ho spustíš podruhé tak to hlásí tu chybu s tím file descriptorem. No a v případě té chyby není něco zapsáno v logu jádra (zjistíš příkazem dmesg)? Skript celkově mi přijde v pořádku, snad jen na konec bych dal (ale spíš jen z programátorské slušnosti, Python po skončení otevřené soubory zavírá sám, ale jistota je jistota) vepa.close().

[Dadam]

V podstatě ano, jen chyby nehlásí skript, ale program bfin-elf-ldr, který nahrává firmware do zařízení (přes ten stejný port). Ten prochází do té doby, než spustím skript (skript je klient, který komunikuje se zařízením, do kterého nahrávám kód přes bfin-elf-ldr). V dmesg mám jen zprávu o připojení USB zařízení. Volání close() tu nemám, ale jiný skript (taky PySerial) ho měl, docházelo ke stejné chybě. Abych to ujasnil definitivně:

start počítače
připojení zařízení
bfin-elf-ldr: projde
reset zařízení
bfin-elf-ldr: projde
reset zařízení
bfin-elf-ldr: projde

skript: projde
reset zařízení
bfin-elf-ldr: Bad file descriptor
odpojení a připojení zařízení
bfin-elf-ldr: Bad file descriptor

otevření portu v Cutecom
bfin-elf-ldr: projde
zavření portu v Cutecom
reset zařízení
bfin-elf-ldr: Bad file descriptor

restart počítače
bfin-elf-ldr: projde
skript: projde
reset zařízení
bfin-elf-ldr: Bad file descriptor

Vynechané řádky jsou jen pro přehlednost, zařízení se resetuje vlastním tlačítkem, vlastní zdroj energie nemá. Zkoušel jsem i vypsat debugovací informace toho programátoru:

Opening /dev/ttyUSB1 ... OK!
Configuring terminal I/O ... [getattr] [setattr] [speed:115200] OK!
Trying to send autobaud ... OK!
Trying to read autobaud ... Failed: Bad file descriptor

read autobaud je čtení binárních hodnot, které pošle zařízení, v podstatě jen kontrola jestli se nastavilo správně

[Pavel Stárek]

No a co postup:

restart počítače
skript
chvilku počkat
skript

Jestli on ten skript tam nepošle něco, co nějak rozhodí destičku s tím Bfinem (ale proč by pak to otevření portu v terminálu mělo vliv? - leda něco s RTS/CTS DTR/DSR - nevím). Ten PySerial dělá naprosto standardní operace, však se do něj můžeš podívat, nedělá tam nijaká zvěrstva.

[Dadam]

Skript můžu použít kolikrát chci; RTS/CTS ani DTR/DSR na desce není zapojené. Co mě mate je fakt, že skript udělá něco s portem, já odpojím zařízení (tím zmizí deskriptor či jak se říká souboru v /dev) a čekal bych, že veškerá nastavení budou pryč. Zase ho připojím a to něco je pořád nastavené. Existují nějaké informace, které se o sériovém portu takto standardně uchovají?

[Pavel Stárek]

Nevím o tom, že by se někde uchovávaly nějaké informace o nastavení sériového portu. Po odpojení zařízení je toto odebráno z /dev, tedy jeho "speciální" soubor - neboli device file (odebírání a přidávání má na starosti většinou program udev). To asi nemá s tou chybou toho bfin-ldr nic společného.

[Dadam]

Jako berličku jsem zkusil skript, který otevře port a čeká na signál. Ten spustím, odešlu do pozadí, spustím loader a po jeho doběhnutí pošlu signál. Skript jsem udělal v pySerial a nepomohl. Takže otevření portu v Cutecom pomůže, otevření portu v pySerial ne.

[Pavel Stárek]

To by se pak muselo pomocí prográmku strace zjistit, co dělá pySerial a co Cutecom. Přijde mi, že Cutecom udělá něco navíc, ale nevím co. Jinak použití strace:

strace -o cutecom.log cutecom

strace -o pyserial.log python skript.py

[Dadam]

Přesně takový nástroj jsem potřeboval, jen jsem ho použil i přímo na loader. Výsledky:

1. Zámky:
Úspěšná a neúspěšná verze se prvě liší voláním

open("//var/lock/LCK..ttyUSB1", O_RDONLY) = -1 ENOENT (No such file or directory)

po kterém následuje

open("//var/lock/LCK..ttyUSB1", O_WRONLY|O_CREAT|O_EXCL, 0666) = 4

a dva pokusy o uzavření, jeden ok a jeden s chybou BADF (uzavírá se uzavřený deskriptor). Úspěšná verze otevře zámek hned napoprvé.
2. Bug:
Udělali si funkci read_retry(), která při přerušeném nebo nedokončeném volání read() zkusí přečíst zbytek. Používají ji ve funkci ldr_load_uart(). Jenže když read() vrátí 0, funkci ukončí, kousek dál v kódu to považují za chybu a volají perror(), který vypíše BADF z bodu 1, v strace žádné jiné volání BADF negeneruje.

Odkazy jsou na zdrojáky.

V strace logu cutecom ani loaderu jsem použití zámků nenašel (hledal jsem ttyUSB1), nicméně by se jednalo přesně o ten druh "informace", který jsem si představoval že může zůstat pozměněný mezi odpojením a připojením zařízení. Bylo by to možné?

Může read() vrátit nulu místo EAGAIN, když nejsou k dispozici data? V read_retry() testují jen na EINTR. Po přednášce se zkusím podívat jestli nějak jinak nenastavují vlastnosti portů.

Log z cutecom:

open("/dev/ttyUSB1", O_RDWR|O_NONBLOCK) = 9
ioctl(9, TCFLSH, 0x2)                   = 0
fcntl64(9, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl64(9, F_SETFL, O_RDWR)             = 0
ioctl(9, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(9, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(9, SNDCTL_TMR_START or SNDRV_TIMER_IOCTL_TREAD or TCSETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(9, TIOCMGET, [TIOCM_DTR|TIOCM_RTS]) = 0
ioctl(9, TIOCMSET, [TIOCM_DTR|TIOCM_RTS]) = 0
ioctl(9, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(9, SNDCTL_TMR_START or SNDRV_TIMER_IOCTL_TREAD or TCSETS, {B115200 -opost -isig -icanon -echo ...}) = 0
..... věci mimo
ioctl(9, SNDCTL_TMR_START or SNDRV_TIMER_IOCTL_TREAD or TCSETS, {B115200 -opost -isig -icanon -echo ...}) = 0
close(9)                                = 0

Log z python skriptu:

open("/dev/ttyUSB1", O_RDWR|O_NOCTTY|O_NONBLOCK|O_LARGEFILE) = 3
ioctl(3, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(3, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(3, SNDCTL_TMR_START or SNDRV_TIMER_IOCTL_TREAD or TCSETS, {B115200 -opost -isig -icanon -echo ...}) = 0
write(1, "python-wrapper: Closing port\n", 29) = 29
close(3)                                = 0

[Pavel Stárek]

Podle těch výpisů se s tím portem neděje nic zvláštního, snad jen cutecom shazuje RTS a python ho otevírá s trošku jinými flagy (ale jestli to má vliv na funkci bfin-ldr netuším). No, bohužel ti v tomto asi dál neporadím, ale našel sem tvůj dotaz ve fóru přímo u zdroje (bfin.uclinux.org), tak snad ti tam někdo poradí odborněji.

[Pavel Stárek]

Ale jo, přeci jen jsem si něčeho všimnul. Stáhnul jsem si ty logy celé z bfinu a je tam rozdíl v success.log na řádku 90 je:

ioctl(4, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0

avšak ve failure.log je na řádku 82 (nevím proč je to o osm řádků dřív, ale to je jedno):

ioctl(4, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, {B921600 -opost -isig -icanon -echo ...}) = 0

Takže jednou to nastavuje baudrate 115200 a jednou zase baudrate 921600 ale v zápětí ob dva řádky se nastavuje správně 115200. No a taky to prostě nenačte ty 4 bajty pro ten autobaud. Ale proč? Přeci ten python po sobě prostě port uzavře, a tím to hasne nevím, kde se tam vzalo to 921600. Stále více mám podezření, že chyba bude někde jinde, ale ne v linuxu nebo pythonu. No ale jestli toto moje zjištění k něčemu bude nevím. Ještě takový dotaz: musí se používat ta autobaud metoda pro tu komunikaci? Já tyto automatiky a obzvlášť na sériovém portu moc nemusím

[Dadam]

Tak je to "vyřešené" zásahem do zdrojáku. Zdá se že ten loader začne číst deskriptor dřív než jsou k dispozici data, takže vložit sleep(1) nebo opakovat read() když předchozí volání vrátí 0. Mimochodem to, aby se jim to nekouslo v read(), když zažízení odmítne poslat data, mají udělané pomocí alert(), docela zajímací funkce. Uvidím co s tím udělá Mike, doufám že to dopadne líp než jeho poslední pokus:

Pokud se nepoužije ani jeden "upgrade", tak už to nehlásí

Failed: Bad file descriptor

ale (SVN log: clear errno when reading to avoid confusing error output)

Failed: Success

Nastavení je o osm řádků výš, protože se při failu nemanipuluje s prvním zámkem, jehož otevření skončilo chybou, a autobaud nutný je, respektive je v boot kernelu a do toho hrabat nebudu

Pořád zbývá otázka co s tím dělá ten Python, že nejde otevřít zámek a pozdrží se příjem dat...

[Pavel Stárek]

Pořád zbývá otázka co s tím dělá ten Python, že nejde otevřít zámek a pozdrží se příjem dat...

Stále si myslím že nic zvláštního. Nevím jakou máš verzi pyserial ale ve verzi 2.5 se opravdu neděje nic zvláštního, když se kouknu do zdrojáků. Ještě by to chtělo vyzkoušet na PC s "opravdovým" sériovým portem, ne s USB2RS232 redukcí. To zamykání klidně může být nějaká featůra linuxového usbserial.

[Dadam]

To bude trochu problém, ta redukce je v desce. Nějaký debugovací výstup to má (mezi Blackfinem a redukcí), ale byl by potřeba převodník. Zkusím něco sehnat.

Zamykání je v rámci loaderu:

/*
 * tty_lock()
 * Try to lock the specified tty.  Return value indicates
 * whether locking was successful.
 */
bool tty_lock(const char *tty)
{
	int fd, mask;
	bool ret = false;
	FILE *fp;
	const char *lockfile;

	/* if the lock dir is not available, just lie and say
	 * the locking worked out for us.
	 */
	if (!_tty_check_lock_dir())
		return true;

	/* see if the lock is stale */
	lockfile = _tty_get_lock_name(tty);
	fp = fopen(lockfile, "rb");
	if (fp != NULL) {
		unsigned long pid;
		if (fscanf(fp, "%lu", &pid) == 1) {
			if (kill(pid, 0) == -1 && errno == ESRCH) {
				if (!quiet)
					printf("Removing stale lock '%s'\n", lockfile);
				unlink(lockfile);
			} else if (verbose)
				printf("TTY '%s' is locked by pid '%lu'\n", tty, pid);
		}
		fclose(fp);
	}

	/* now create a new lock and write our pid into it */
	mask = umask(022);
	fd = open(lockfile, O_WRONLY | O_CREAT | O_EXCL | O_BINARY, 0666);
	umask(mask);
	if (fd != -1) {
		fp = fdopen(fd, "wb");
		if (fp != NULL) {
			fprintf(fp, "%lu\n", (unsigned long)getpid());
			fclose(fp);
			ret = true;
		} else
			/* the fclose() above also calls close() on the underlying fd */
			close(fd);
	}

	return ret;
}

[Dadam]

<teorie>

Ti dacani při otevírání nepracují s O_NONBLOCK. Takže při prvním otevření je nastavené blokující čtení, read() nikdy nevrátí nulu. Pak spustím skript, který nastaví čtení neblokující, read() vrací 0 a Failed: Success

</teorie>

Otázka by byla proč to funguje když to otevřu v Cutecom, proč nepomůže otevření v Pythonu (oba nastavují neblokující) a proč to přetrvá i přes odpojení zařízení.

[Dadam]

Tímto to není. Když jsem nastavil rychlost v cutecom na 115200, rychlosti byly stejné. Navíc v SVN verzi toho loaderu nepoužívají ani ty zámky, takže momentálně mám dva identické logy (liší se jen hodnotami ukazatelů), jen v jednom read() přečte 4 bajty, ve druhém nic.