search

arduino / arduino-cli

Arduino command line tool
https://arduino.github.io/arduino-cli/latest/
GNU General Public License v3.0
4.35k stars 381 forks source link

Bug: IDE shows avrdude output out-of-order #1825

Open gwideman opened 2 years ago

gwideman commented 2 years ago

When burning a bootloader, the IDE runs avrdude twice in sequence. At least, they should be in sequence (not parallel) because they use the same programmer to interact with the board being programmed.

However, the console output window of the IDE shows the second command being issued before the output of the first command has completed. This is probably a bug in the buffering of avrdude's output (stderr, maybe stdout) on its way to display on the IDE's console window.

This is with IDE 1.8.19 on Windows 10 (with current updates). Only one instance of the IDE application and window was running. IDE preferences set to verbose.

Below is an example output. Note the second invocation of avrdude is followed by about 28 lines of additional output from the first command before the second command shows avrdude's startup Version message.

C:\Users\graham\AppData\Local\Arduino15\packages\arduino\tools\avrdude\6.3.0-arduino17/bin/avrdude -CC:\Users\graham\AppData\Local\Arduino15\packages\arduino\tools\avrdude\6.3.0-arduino17/etc/avrdude.conf -v -patmega168p -cstk500v1 -PCOM7 -b19200 -e -Ulock:w:0x3F:m -Uefuse:w:0x04:m -Uhfuse:w:0b11011111:m -Ulfuse:w:0xE0:m 

avrdude: Version 6.3-20190619
         Copyright (c) 2000-2005 Brian Dean, http://www.bdmicro.com/
         Copyright (c) 2007-2014 Joerg Wunsch

         System wide configuration file is "C:\Users\graham\AppData\Local\Arduino15\packages\arduino\tools\avrdude\6.3.0-arduino17/etc/avrdude.conf"

         Using Port                    : COM7
         Using Programmer              : stk500v1
         Overriding Baud Rate          : 19200
         AVR Part                      : ATmega168P
         Chip Erase delay              : 9000 us
         PAGEL                         : PD7
         BS2                           : PC2
         RESET disposition             : dedicated
         RETRY pulse                   : SCK
         serial program mode           : yes
         parallel program mode         : yes
         Timeout                       : 200
         StabDelay                     : 100
         CmdexeDelay                   : 25
         SyncLoops                     : 32
         ByteDelay                     : 0
         PollIndex                     : 3
         PollValue                     : 0x53
         Memory Detail                 :

                                  Block Poll               Page                       Polled
           Memory Type Mode Delay Size  Indx Paged  Size   Size #Pages MinW  MaxW   ReadBack
           ----------- ---- ----- ----- ---- ------ ------ ---- ------ ----- ----- ---------
           eeprom        65    20     4    0 no        512    4      0  3600  3600 0xff 0xff
           flash         65     6   128    0 yes     16384  128    128  4500  4500 0xff 0xff
           lfuse          0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
           hfuse          0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
           efuse          0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
           lock           0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
           calibration    0     0     0    0 no          1    0      0     0     0 0x00 0x00
           signature      0     0     0    0 no          3    0      0     0     0 0x00 0x00

         Programmer Type : STK500
         Description     : Atmel STK500 Version 1.x firmware
         Hardware Version: 2
         Firmware Version: 1.18
         Topcard         : Unknown
         Vtarget         : 0.0 V
         Varef           : 0.0 V
         Oscillator      : Off
         SCK period      : 0.1 us

avrdude: AVR device initialized and ready to accept instructions

Reading | ################################################## | 100% 0.02s

avrdude: Device signature = 0x1e940b (probably m168p)
avrdude: erasing chip
avrdude: reading input file "0x3F"
avrdude: writing lock (1 bytes):

Writing | ################################################## | 100% 0.01s

avrdude: 1 bytes of lock written
avrdude: verifying lock memory against 0x3F:
avrdude: load data lock data from input file 0x3F:
avrdude: input file 0x3F contains 1 bytes
avrdude: reading on-chip lock data:

Reading | ################################################## | 100% 0.01s

avrdude: verifying ...
avrdude: 1 bytes of lock verified
avrdude: reading input file "0x04"
avrdude: writing efuse (1 bytes):

Writing |  ***failed;  
################################################## | 100% 0.07s

avrdude: 1 bytes of efuse written
avrdude: verifying efuse memory against 0x04:
avrdude: load data efuse data from input file 0x04:
avrdude: input file 0x04 contains 1 bytes
avrdude: reading on-chip efuse data:

Reading | ################################################## | 100% 0.01s

avrdude: verifying ...
avrdude: WARNING: invalid value for unused bits in fuse "efuse", should be set to 1 according to datasheet
This behaviour is deprecated and will result in an error in future version
You probably want to use 0xfc instead of 0x04 (double check with your datasheet first).
avrdude: 1 bytes of efuse verified
avrdude: reading input file "0b11011111"
avrdude: writing hfuse (1 bytes):

C:\Users\graham\AppData\Local\Arduino15\packages\arduino\tools\avrdude\6.3.0-arduino17/bin/avrdude -CC:\Users\graham\AppData\Local\Arduino15\packages\arduino\tools\avrdude\6.3.0-arduino17/etc/avrdude.conf -v -patmega168p -cstk500v1 -PCOM7 -b19200 -Uflash:w:C:\Users\graham\AppData\Local\Arduino15\packages\diy_atmega8_series\hardware\avr\2020.10.9/bootloaders/optiboot_atmega168p_16000000L_57600.hex:i -Ulock:w:0x3F:m 
Writing | ################################################## | 100% 0.01s

avrdude: 1 bytes of hfuse written
avrdude: verifying hfuse memory against 0b11011111:
avrdude: load data hfuse data from input file 0b11011111:
avrdude: input file 0b11011111 contains 1 bytes
avrdude: reading on-chip hfuse data:

Reading | ################################################## | 100% 0.01s

avrdude: verifying ...
avrdude: 1 bytes of hfuse verified
avrdude: reading input file "0xE0"
avrdude: writing lfuse (1 bytes):

Writing | ################################################## | 100% 0.01s

avrdude: 1 bytes of lfuse written
avrdude: verifying lfuse memory against 0xE0:
avrdude: load data lfuse data from input file 0xE0:
avrdude: input file 0xE0 contains 1 bytes
avrdude: reading on-chip lfuse data:

Reading | ################################################## | 100% 0.01s

avrdude: verifying ...
avrdude: 1 bytes of lfuse verified

avrdude done.  Thank you.

avrdude: Version 6.3-20190619
         Copyright (c) 2000-2005 Brian Dean, http://www.bdmicro.com/
         Copyright (c) 2007-2014 Joerg Wunsch

         System wide configuration file is "C:\Users\graham\AppData\Local\Arduino15\packages\arduino\tools\avrdude\6.3.0-arduino17/etc/avrdude.conf"

         Using Port                    : COM7
         Using Programmer              : stk500v1
         Overriding Baud Rate          : 19200
         AVR Part                      : ATmega168P
         Chip Erase delay              : 9000 us
         PAGEL                         : PD7
         BS2                           : PC2
         RESET disposition             : dedicated
         RETRY pulse                   : SCK
         serial program mode           : yes
         parallel program mode         : yes
         Timeout                       : 200
         StabDelay                     : 100
         CmdexeDelay                   : 25
         SyncLoops                     : 32
         ByteDelay                     : 0
         PollIndex                     : 3
         PollValue                     : 0x53
         Memory Detail                 :

                                  Block Poll               Page                       Polled
           Memory Type Mode Delay Size  Indx Paged  Size   Size #Pages MinW  MaxW   ReadBack
           ----------- ---- ----- ----- ---- ------ ------ ---- ------ ----- ----- ---------
           eeprom        65    20     4    0 no        512    4      0  3600  3600 0xff 0xff
           flash         65     6   128    0 yes     16384  128    128  4500  4500 0xff 0xff
           lfuse          0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
           hfuse          0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
           efuse          0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
           lock           0     0     0    0 no          1    0      0  4500  4500 0x00 0x00
           calibration    0     0     0    0 no          1    0      0     0     0 0x00 0x00
           signature      0     0     0    0 no          3    0      0     0     0 0x00 0x00

         Programmer Type : STK500
         Description     : Atmel STK500 Version 1.x firmware
         Hardware Version: 2
         Firmware Version: 1.18
         Topcard         : Unknown
         Vtarget         : 0.0 V
         Varef           : 0.0 V
         Oscillator      : Off
         SCK period      : 0.1 us

avrdude: AVR device initialized and ready to accept instructions

Reading | ################################################## | 100% 0.02s

avrdude: Device signature = 0x1e940b (probably m168p)
avrdude: NOTE: "flash" memory has been specified, an erase cycle will be performed
         To disable this feature, specify the -D option.
avrdude: erasing chip
avrdude: reading input file "C:\Users\graham\AppData\Local\Arduino15\packages\diy_atmega8_series\hardware\avr\2020.10.9/bootloaders/optiboot_atmega168p_16000000L_57600.hex"
avrdude: writing flash (16384 bytes):

Writing | ################################################## | 100% 0.00s

avrdude: 16384 bytes of flash written
avrdude: verifying flash memory against C:\Users\graham\AppData\Local\Arduino15\packages\diy_atmega8_series\hardware\avr\2020.10.9/bootloaders/optiboot_atmega168p_16000000L_57600.hex:
avrdude: load data flash data from input file C:\Users\graham\AppData\Local\Arduino15\packages\diy_atmega8_series\hardware\avr\2020.10.9/bootloaders/optiboot_atmega168p_16000000L_57600.hex:
avrdude: input file C:\Users\graham\AppData\Local\Arduino15\packages\diy_atmega8_series\hardware\avr\2020.10.9/bootloaders/optiboot_atmega168p_16000000L_57600.hex contains 16384 bytes
avrdude: reading on-chip flash data:

Reading | ################################################## | 100% -0.00s

avrdude: verifying ...
avrdude: 16384 bytes of flash verified
avrdude: reading input file "0x3F"
avrdude: writing lock (1 bytes):

Writing | ################################################## | 100% 0.01s

avrdude: 1 bytes of lock written
avrdude: verifying lock memory against 0x3F:
avrdude: load data lock data from input file 0x3F:
avrdude: input file 0x3F contains 1 bytes
avrdude: reading on-chip lock data:

Reading | ################################################## | 100% 0.01s

avrdude: verifying ...
avrdude: 1 bytes of lock verified

avrdude done.  Thank you.
cmaglie commented 1 year ago

@umbynos could you verify if this happens with the latest avrdude?