search

riscv-collab / riscv-openocd

Fork of OpenOCD that has RISC-V support
Other
438 stars 319 forks source link

Error: Debug Module did not become active. #427

Closed shirlynan closed 4 years ago

shirlynan commented 4 years ago

Hello,

I got the error message "Error: Debug Module did not become active. dmcontrol=0x3ff0000" when I tried to debug the core with J-Link. What does this error mean exactly? The same design works on another xilinx fpga board, jlink can connect to the target through openocd correctly.

Thanks for your help.

timsifive commented 4 years ago

dmcontrol.dmactive (bit 0 of dmcontrol) should become set after the debugger sets it, and that didn't happen. If you reproduce this failure running openocd with -d and attach the complete output here, I'll take a look.

shirlynan commented 4 years ago

dmcontrol.dmactive (bit 0 of dmcontrol) should become set after the debugger sets it, and that didn't happen. If you reproduce this failure running openocd with -d and attach the complete output here, I'll take a look.

Thanks for your reply. I reduced the Jtag frequency from 10000khz to 4000khz. Sometimes the connection could be successfully established but sometimes not but gave me another error message: "Error: failed read (NOP) at 0x11, status=2". With different Jtag frequency openocd gave me different responses, so I can't say with which frequency it works... But before I can always use 10000khz for debugging with the same design but for another board (different model).

Here is the debug output of the dmactive error: Debug: 199 281 jlink.c:580 jlink_init(): Using libjaylink 0.2.0 (compiled with 0.2.0). Debug: 200 309 jlink.c:534 jaylink_log_handler(): Found device (VID:PID = 1366:0101, bus:address = 003:011). Debug: 201 311 jlink.c:534 jaylink_log_handler(): Device: USB address = 0. Debug: 202 312 jlink.c:534 jaylink_log_handler(): Device: Serial number = 261001011. Debug: 203 312 jlink.c:534 jaylink_log_handler(): Allocating new device instance. Debug: 204 312 jlink.c:534 jaylink_log_handler(): Found 1 USB device(s). Debug: 205 312 jlink.c:534 jaylink_log_handler(): Trying to open device (bus:address = 003:011). Debug: 206 312 jlink.c:534 jaylink_log_handler(): Using endpoint 81 (IN) and 01 (OUT). Debug: 207 312 jlink.c:534 jaylink_log_handler(): Device opened successfully. Info : 215 315 jlink.c:704 jlink_init(): J-Link V11 compiled Aug 14 2019 16:21:09 Info : 228 317 jlink.c:745 jlink_init(): Hardware version: 11.00 Info : 237 318 jlink.c:787 jlink_init(): VTarget = 3.328 V Debug: 243 318 jlink.c:534 jaylink_log_handler(): Last read operation left 16 bytes in the buffer. Debug: 253 319 jlink.c:939 jlink_reset(): TRST: 0, SRST: 0. Debug: 272 323 core.c:1599 adapter_khz_to_speed(): convert khz to interface specific speed value Debug: 273 323 core.c:1603 adapter_khz_to_speed(): have interface set up Debug: 280 324 core.c:1599 adapter_khz_to_speed(): convert khz to interface specific speed value Debug: 281 324 core.c:1603 adapter_khz_to_speed(): have interface set up Info : 282 324 core.c:1381 adapter_init(): clock speed 10000 kHz Debug: 283 324 openocd.c:141 handle_init_command(): Debug Adapter init complete Debug: 284 324 command.c:143 script_debug(): command - transport transport init Debug: 286 324 transport.c:239 handle_transport_init(): handle_transport_init Debug: 287 324 jlink.c:939 jlink_reset(): TRST: 0, SRST: 0. Debug: 292 324 core.c:729 jtag_add_reset(): SRST line released Debug: 293 325 core.c:753 jtag_add_reset(): TRST line released Debug: 294 325 core.c:327 jtag_call_event_callbacks(): jtag event: TAP reset Debug: 295 325 command.c:143 script_debug(): command - jtag jtag arp_init Debug: 296 325 core.c:1394 jtag_init_inner(): Init JTAG chain Debug: 297 325 core.c:327 jtag_call_event_callbacks(): jtag event: TAP reset Debug: 306 326 core.c:1060 jtag_examine_chain(): DR scan interrogation for IDCODE/BYPASS Debug: 307 326 core.c:327 jtag_call_event_callbacks(): jtag event: TAP reset Info : 316 363 core.c:959 jtag_examine_chain_display(): JTAG tap: riscv.cpu tap/device found: 0x00000913 (mfg: 0x489 (SiFive Inc), part: 0x0000, ver: 0x0) Debug: 317 363 core.c:1190 jtag_validate_ircapture(): IR capture validation scan Debug: 326 364 core.c:1248 jtag_validate_ircapture(): riscv.cpu: IR capture 0x01 Debug: 327 364 command.c:143 script_debug(): command - dap dap init Debug: 329 364 arm_dap.c:105 dap_init_all(): Initializing all DAPs ... Debug: 330 364 openocd.c:158 handle_init_command(): Examining targets... Debug: 331 364 target.c:1609 target_call_event_callbacks(): target event 17 (examine-start) for core riscv.cpu Debug: 332 364 riscv.c:972 riscv_examine(): riscv_examine() Debug: 341 366 riscv.c:402 dtmcontrol_scan(): DTMCONTROL: 0x0 -> 0x1071 Debug: 342 366 riscv.c:982 riscv_examine(): dtmcontrol=0x1071 Debug: 343 366 riscv.c:984 riscv_examine(): version=0x1 Debug: 344 366 riscv-013.c:1771 init_target(): init Debug: 353 366 riscv-013.c:452 dtmcontrol_scan(): DTMCS: 0x0 -> 0x1071 Debug: 354 366 riscv-013.c:1510 examine(): dtmcontrol=0x1071 Debug: 355 366 riscv-013.c:1511 examine(): dmireset=0 Debug: 356 366 riscv-013.c:1512 examine(): idle=1 Debug: 357 366 riscv-013.c:1513 examine(): dmistat=0 Debug: 358 366 riscv-013.c:1514 examine(): abits=7 Debug: 359 366 riscv-013.c:1515 examine(): version=1 Debug: 360 366 riscv-013.c:263 get_dm(): [0] Allocating new DM Debug: 369 367 riscv-013.c:397 scan(): 41b 0i w 00000000 @10 -> + 00000000 @00 Debug: 378 367 riscv-013.c:397 scan(): 41b 0i - 00000000 @10 -> + 03ff0000 @10 Debug: 379 367 riscv-013.c:408 scan(): -> hartsello=1023 Debug: 388 368 riscv-013.c:397 scan(): 41b 0i w 00000001 @10 -> + 00000000 @00 Debug: 389 368 riscv-013.c:408 scan(): dmactive -> Debug: 398 368 riscv-013.c:397 scan(): 41b 0i - 00000000 @10 -> + 00000000 @10 Debug: 407 368 riscv-013.c:397 scan(): 41b 0i w 07ffffc1 @10 -> + 00000000 @00 Debug: 408 368 riscv-013.c:408 scan(): hasel hartselhi=1023 hartsello=1023 dmactive -> Debug: 417 369 riscv-013.c:397 scan(): 41b 0i - 00000000 @10 -> + 00000000 @10 Debug: 426 369 riscv-013.c:397 scan(): 41b 0i r 00000000 @10 -> + 00000000 @00 Debug: 435 369 riscv-013.c:397 scan(): 41b 0i - 00000000 @10 -> + 03ff0000 @10 Debug: 436 369 riscv-013.c:408 scan(): -> hartsello=1023 Error: 437 369 riscv-013.c:1549 examine(): Debug Module did not become active. dmcontrol=0x3ff0000 Debug: 438 369 openocd.c:160 handle_init_command(): target examination failed Debug: 439 369 command.c:143 script_debug(): command - flash flash init Debug: 441 369 tcl.c:1222 handle_flash_init_command(): Initializing flash devices... Debug: 442 369 command.c:143 script_debug(): command - nand nand init Debug: 444 369 tcl.c:498 handle_nand_init_command(): Initializing NAND devices... Debug: 445 369 command.c:143 script_debug(): command - pld pld init Debug: 447 369 pld.c:206 handle_pld_init_command(): Initializing PLDs... Debug: 448 369 gdb_server.c:3418 gdb_target_start(): starting gdb server for riscv.cpu on 3333 Info : 449 370 server.c:311 add_service(): Listening on port 3333 for gdb connections Debug: 450 370 command.c:143 script_debug(): command - halt halt Debug: 452 370 target.c:3059 handle_halt_command(): - Error: 453 370 target.c:567 target_halt(): Target not examined yet Debug: 454 370 command.c:630 run_command(): Command 'halt' failed with error code -4 User : 455 370 command.c:695 command_run_line(): Debug: 456 370 riscv.c:476 riscv_deinit_target(): riscv_deinit_target() Debug: 457 370 riscv-013.c:1486 deinit_target(): riscv_deinit_target() Debug: 458 370 target.c:1959 target_free_all_working_areas_restore(): freeing all working areas Debug: 464 370 jlink.c:534 jaylink_log_handler(): Last read operation left 16 bytes in the buffer. Debug: 466 370 jlink.c:534 jaylink_log_handler(): Closing device (bus:address = 003:011). Debug: 467 370 jlink.c:534 jaylink_log_handler(): Device closed successfully. Debug: 468 370 jlink.c:534 jaylink_log_handler(): Device destroyed (bus:address = 003:011).

And here is the debug output of the NOP error:

Debug: 199 27 jlink.c:580 jlink_init(): Using libjaylink 0.2.0 (compiled with 0.2.0). Debug: 200 31 jlink.c:534 jaylink_log_handler(): Found device (VID:PID = 1366:0101, bus:address = 003:011). Debug: 201 32 jlink.c:534 jaylink_log_handler(): Device: USB address = 0. Debug: 202 32 jlink.c:534 jaylink_log_handler(): Device: Serial number = 261001011. Debug: 203 32 jlink.c:534 jaylink_log_handler(): Allocating new device instance. Debug: 204 32 jlink.c:534 jaylink_log_handler(): Found 1 USB device(s). Debug: 205 32 jlink.c:534 jaylink_log_handler(): Trying to open device (bus:address = 003:011). Debug: 206 32 jlink.c:534 jaylink_log_handler(): Using endpoint 81 (IN) and 01 (OUT). Debug: 207 32 jlink.c:534 jaylink_log_handler(): Device opened successfully. Info : 215 35 jlink.c:704 jlink_init(): J-Link V11 compiled Aug 14 2019 16:21:09 Info : 228 36 jlink.c:745 jlink_init(): Hardware version: 11.00 Info : 237 37 jlink.c:787 jlink_init(): VTarget = 3.328 V Debug: 243 40 jlink.c:534 jaylink_log_handler(): Last read operation left 16 bytes in the buffer. Debug: 253 40 jlink.c:939 jlink_reset(): TRST: 0, SRST: 0. Debug: 272 45 core.c:1599 adapter_khz_to_speed(): convert khz to interface specific speed value Debug: 273 45 core.c:1603 adapter_khz_to_speed(): have interface set up Debug: 280 45 core.c:1599 adapter_khz_to_speed(): convert khz to interface specific speed value Debug: 281 45 core.c:1603 adapter_khz_to_speed(): have interface set up Info : 282 45 core.c:1381 adapter_init(): clock speed 4500 kHz Debug: 283 45 openocd.c:141 handle_init_command(): Debug Adapter init complete Debug: 284 45 command.c:143 script_debug(): command - transport transport init Debug: 286 45 transport.c:239 handle_transport_init(): handle_transport_init Debug: 287 45 jlink.c:939 jlink_reset(): TRST: 0, SRST: 0. Debug: 292 47 core.c:729 jtag_add_reset(): SRST line released Debug: 293 47 core.c:753 jtag_add_reset(): TRST line released Debug: 294 47 core.c:327 jtag_call_event_callbacks(): jtag event: TAP reset Debug: 295 47 command.c:143 script_debug(): command - jtag jtag arp_init Debug: 296 47 core.c:1394 jtag_init_inner(): Init JTAG chain Debug: 297 47 core.c:327 jtag_call_event_callbacks(): jtag event: TAP reset Debug: 306 48 core.c:1060 jtag_examine_chain(): DR scan interrogation for IDCODE/BYPASS Debug: 307 48 core.c:327 jtag_call_event_callbacks(): jtag event: TAP reset Info : 316 50 core.c:959 jtag_examine_chain_display(): JTAG tap: riscv.cpu tap/device found: 0x00000913 (mfg: 0x489 (SiFive Inc), part: 0x0000, ver: 0x0) Debug: 317 50 core.c:1190 jtag_validate_ircapture(): IR capture validation scan Debug: 326 50 core.c:1248 jtag_validate_ircapture(): riscv.cpu: IR capture 0x01 Debug: 327 50 command.c:143 script_debug(): command - dap dap init Debug: 329 50 arm_dap.c:105 dap_init_all(): Initializing all DAPs ... Debug: 330 50 openocd.c:158 handle_init_command(): Examining targets... Debug: 331 50 target.c:1609 target_call_event_callbacks(): target event 17 (examine-start) for core riscv.cpu Debug: 332 50 riscv.c:972 riscv_examine(): riscv_examine() Debug: 341 50 riscv.c:402 dtmcontrol_scan(): DTMCONTROL: 0x0 -> 0x5071 Debug: 342 50 riscv.c:982 riscv_examine(): dtmcontrol=0x5071 Debug: 343 50 riscv.c:984 riscv_examine(): version=0x1 Debug: 344 50 riscv-013.c:1771 init_target(): init Debug: 353 50 riscv-013.c:452 dtmcontrol_scan(): DTMCS: 0x0 -> 0x5071 Debug: 354 50 riscv-013.c:1510 examine(): dtmcontrol=0x5071 Debug: 355 50 riscv-013.c:1511 examine(): dmireset=0 Debug: 356 50 riscv-013.c:1512 examine(): idle=5 Debug: 357 50 riscv-013.c:1513 examine(): dmistat=0 Debug: 358 50 riscv-013.c:1514 examine(): abits=7 Debug: 359 50 riscv-013.c:1515 examine(): version=1 Debug: 360 50 riscv-013.c:263 get_dm(): [0] Allocating new DM Debug: 369 51 riscv-013.c:397 scan(): 41b 0i w 00000000 @10 -> + 000fc082 @11 Debug: 370 51 riscv-013.c:408 scan(): -> allhavereset anyhavereset allresumeack anyresumeack allnonexistent anynonexistent authenticated version=2 Debug: 379 51 riscv-013.c:397 scan(): 41b 0i - 00000000 @10 -> + 03ff0001 @10 Debug: 380 51 riscv-013.c:408 scan(): -> hartsello=1023 dmactive Debug: 389 51 riscv-013.c:397 scan(): 41b 0i w 00000001 @10 -> + 00000000 @00 Debug: 390 51 riscv-013.c:408 scan(): dmactive -> Debug: 399 52 riscv-013.c:397 scan(): 41b 0i - 00000000 @10 -> + 00000000 @10 Debug: 408 52 riscv-013.c:397 scan(): 41b 0i w 07ffffc1 @10 -> + 00000000 @00 Debug: 409 52 riscv-013.c:408 scan(): hasel hartselhi=1023 hartsello=1023 dmactive -> Debug: 418 52 riscv-013.c:397 scan(): 41b 0i - 00000000 @10 -> + 00000001 @10 Debug: 419 52 riscv-013.c:408 scan(): -> dmactive Debug: 428 54 riscv-013.c:397 scan(): 41b 0i r 00000000 @10 -> + 00000000 @00 Debug: 437 55 riscv-013.c:397 scan(): 41b 0i - 00000000 @10 -> + 03ff0001 @10 Debug: 438 55 riscv-013.c:408 scan(): -> hartsello=1023 dmactive Debug: 447 55 riscv-013.c:397 scan(): 41b 0i r 00000000 @11 -> + 00000000 @00 Debug: 456 55 riscv-013.c:397 scan(): 41b 0i - 00000000 @11 -> F 00000000 @00 Error: 457 55 riscv-013.c:655 dmi_op_timeout(): failed read (NOP) at 0x11, status=2 Debug: 458 55 openocd.c:160 handle_init_command(): target examination failed Debug: 459 56 command.c:143 script_debug(): command - flash flash init Debug: 461 56 tcl.c:1222 handle_flash_init_command(): Initializing flash devices... Debug: 462 56 command.c:143 script_debug(): command - nand nand init Debug: 464 56 tcl.c:498 handle_nand_init_command(): Initializing NAND devices... Debug: 465 56 command.c:143 script_debug(): command - pld pld init Debug: 467 56 pld.c:206 handle_pld_init_command(): Initializing PLDs... Debug: 468 56 gdb_server.c:3418 gdb_target_start(): starting gdb server for riscv.cpu on 3333 Info : 469 56 server.c:311 add_service(): Listening on port 3333 for gdb connections Debug: 470 56 command.c:143 script_debug(): command - halt halt Debug: 472 56 target.c:3059 handle_halt_command(): - Error: 473 56 target.c:567 target_halt(): Target not examined yet Debug: 474 56 command.c:630 run_command(): Command 'halt' failed with error code -4 User : 475 56 command.c:695 command_run_line(): Debug: 476 56 riscv.c:476 riscv_deinit_target(): riscv_deinit_target() Debug: 477 56 riscv-013.c:1486 deinit_target(): riscv_deinit_target() Debug: 478 56 target.c:1959 target_free_all_working_areas_restore(): freeing all working areas Debug: 484 56 jlink.c:534 jaylink_log_handler(): Last read operation left 16 bytes in the buffer. Debug: 486 56 jlink.c:534 jaylink_log_handler(): Closing device (bus:address = 003:011). Debug: 487 56 jlink.c:534 jaylink_log_handler(): Device closed successfully. Debug: 488 56 jlink.c:534 jaylink_log_handler(): Device destroyed (bus:address = 003:011).

Thanks for your help.

timsifive commented 4 years ago

Both of these errors are weird.

  1. dmactive is supposed to go high after it's written high but doesn't.
  2. We get an error when reading dmstatus, which I've never seen.

The fact that the behavior changes when you reduce the JTAG frequency makes me think this is something to do with timing or signal integrity on this board. I'd reduce it down to 1MHz or even 100kHz and see if that improves things. I don't see OpenOCD doing anything wrong in these logs.

timsifive commented 4 years ago

Closed due to inactivity.

Yuxin-Yu commented 2 years ago

@shirlynan Hi ,I got the same problem,have you solved it?